[asterisk-bugs] [JIRA] (ASTERISK-26994) Confbridge: CBAnn channels remain when caller hangs up before recording name
James Terhune (JIRA)
noreply at issues.asterisk.org
Thu May 11 13:32:57 CDT 2017
[ https://issues.asterisk.org/jira/browse/ASTERISK-26994?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
James Terhune updated ASTERISK-26994:
-------------------------------------
Attachment: cbann_console_log.txt
Console log
> Confbridge: CBAnn channels remain when caller hangs up before recording name
> ----------------------------------------------------------------------------
>
> Key: ASTERISK-26994
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-26994
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Applications/app_confbridge
> Affects Versions: 13.15.0
> Environment: Ubuntu 16.04
> Reporter: James Terhune
> Severity: Minor
> Attachments: cbann_console_log.txt
>
>
> If a caller to a conference hangs up while playing the prompt to record their name, but before it starts recording, the CBAnn/ channel remains stuck.
> This is reproducible 100% of the time.
> /etc/asterisk/confbridge.conf:
> [general]
> [default_user]
> type=user
> quiet=yes
> [default_bridge]
> type=bridge
> [qsd-confbridge-1]
> type=user
> announce_only_user=yes
> announce_user_count=yes
> quiet=no
> announce_join_leave=yes
> music_on_hold_when_empty=no
> extensions.conf:
> exten => 765,1,Confbridge(qsd-confbridge-1)
> Console log, with debug:
> [May 11 13:16:13] DEBUG[9874]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
> [May 11 13:16:13] DEBUG[9873]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 0
> [May 11 13:16:13] DEBUG[9916]: chan_sip.c:4372 __sip_autodestruct: Auto destroying SIP dialog '59148e1d8abd-jum55u7i5mku'
> [May 11 13:16:13] DEBUG[9916]: chan_sip.c:6600 sip_pvt_dtor: Destroying SIP dialog 59148e1d8abd-jum55u7i5mku
> [May 11 13:16:13] DEBUG[9916]: rtp_engine.c:397 instance_destructor: Destroyed RTP instance '0x7f2630006690'
> [May 11 13:16:14] DEBUG[9916]: chan_sip.c:9451 __find_call: = Looking for Call ID: 59148e2e9e80-pemn84r9y5qv (Checking From) --From tag k1abg1u893 --To-tag
> [May 11 13:16:14] DEBUG[9916]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.101', our source address is '192.168.1.212'.
> [May 11 13:16:14] DEBUG[9916]: chan_sip.c:3921 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.1.212:5060
> [May 11 13:16:14] DEBUG[9916]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.101:5062' into...
> [May 11 13:16:14] DEBUG[9916]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.101' and port '5062'.
> [May 11 13:16:14] DEBUG[9916]: chan_sip.c:9038 __sip_alloc: Allocating new SIP dialog for 59148e2e9e80-pemn84r9y5qv - INVITE (No RTP)
> [May 11 13:16:14] DEBUG[9916][C-00000002]: chan_sip.c:28778 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
> [May 11 13:16:14] DEBUG[9916][C-00000002]: sip/reqresp_parser.c:1711 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces, from-change"
> [May 11 13:16:14] DEBUG[9916][C-00000002]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -timer-
> [May 11 13:16:14] DEBUG[9916][C-00000002]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: timer
> [May 11 13:16:14] DEBUG[9916][C-00000002]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -100rel-
> [May 11 13:16:14] DEBUG[9916][C-00000002]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: 100rel
> [May 11 13:16:14] DEBUG[9916][C-00000002]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -replaces-
> [May 11 13:16:14] DEBUG[9916][C-00000002]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: replaces
> [May 11 13:16:14] DEBUG[9916][C-00000002]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -from-change-
> [May 11 13:16:14] DEBUG[9916][C-00000002]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: from-change
> [May 11 13:16:14] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.101:5062' into...
> [May 11 13:16:14] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.101' and port '5062'.
> [May 11 13:16:14] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.212' into...
> [May 11 13:16:14] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.212' and port ''.
> [May 11 13:16:14] DEBUG[9916][C-00000002]: chan_sip.c:3764 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.101:5062
> [May 11 13:16:14] DEBUG[9916]: chan_sip.c:9451 __find_call: = Looking for Call ID: 59148e2e9e80-pemn84r9y5qv (Checking From) --From tag k1abg1u893 --To-tag as74bc7386
> [May 11 13:16:14] DEBUG[9916][C-00000002]: chan_sip.c:28778 handle_incoming: **** Received ACK (6) - Command in SIP ACK
> [May 11 13:16:14] DEBUG[9916][C-00000002]: chan_sip.c:4548 __sip_ack: Stopping retransmission on '59148e2e9e80-pemn84r9y5qv' of Response 1: Match Found
> [May 11 13:16:15] DEBUG[9916]: chan_sip.c:9451 __find_call: = Looking for Call ID: 59148e2e9e80-pemn84r9y5qv (Checking From) --From tag k1abg1u893 --To-tag
> [May 11 13:16:15] DEBUG[9916]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.212' into...
> [May 11 13:16:15] DEBUG[9916]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.212' and port ''.
> [May 11 13:16:15] DEBUG[9916]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.212' into...
> [May 11 13:16:15] DEBUG[9916]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.212' and port ''.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:28778 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.101:5062' into...
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.101' and port '5062'.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.212' into...
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.212' and port ''.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f2630006180'
> [May 11 13:16:15] DEBUG[9916][C-00000002]: res_rtp_asterisk.c:2727 ast_rtp_new: Allocated port 17212 for RTP instance '0x7f2630006180'
> [May 11 13:16:15] DEBUG[9916][C-00000002]: res_rtp_asterisk.c:2755 ast_rtp_new: Creating ICE session 0.0.0.0:17212 (17212) for RTP instance '0x7f2630006180'
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.212' into...
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.212' and port ''.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.212' into...
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.212' and port ''.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x7f2630006180' is setup and ready to go
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'disasterisk' into...
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'disasterisk' and port ''.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: res_rtp_asterisk.c:5116 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f2630006180'
> == Using SIP RTP CoS mark 5
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:5809 do_setnat: Setting NAT on RTP to On
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10343 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10343 process_sdp: Processing session-level SDP o=root 2054384040 2054384040 IN IP4 192.168.1.101... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10343 process_sdp: Processing session-level SDP s=call... UNSUPPORTED OR FAILED.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.101' into...
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.101' and port ''.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10343 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.101... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10343 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7f25cb8dc000
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f25cb8dc000
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f25cb8dc000
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f25cb8dc000
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 99 based on m type on 0x7f25cb8dc000
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:684 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 108 format for m type on 0x7f25cb8dc000
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f25cb8dc000
> [May 11 13:16:15] WARNING[9916][C-00000002]: chan_sip.c:33901 process_crypto: Ignoring crypto attribute in SDP because RTP transport is insecure
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:Ou17n08jR7w9NWPdyedLXPgNG/q+8jbTqbOwSa9B... UNSUPPORTED OR FAILED.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:99 G726-32/8000... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:108 AAL2-G726-32/8000... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.101', our source address is '192.168.1.212'.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: res_rtp_asterisk.c:5174 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f2630006180'
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7f26300053a8) from 0x7f25cb8dc000 to 0x7f2630006348
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7f2630000f68) from 0x7f25cb8dc000 to 0x7f2630006348
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f2630005448) from 0x7f25cb8dc000 to 0x7f2630006348
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x7f2630005338) from 0x7f25cb8dc000 to 0x7f2630006348
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 18 (0x7f263000e058) from 0x7f25cb8dc000 to 0x7f2630006348
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 99 (0x7f2630000fd8) from 0x7f25cb8dc000 to 0x7f2630006348
> [May 11 13:16:15] DEBUG[9916][C-00000002]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 108 (0x7f2630001078) from 0x7f25cb8dc000 to 0x7f2630006348
> [May 11 13:16:15] DEBUG[9916][C-00000002]: res_rtp_asterisk.c:5015 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f2630006180'
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:11097 process_sdp: We're settling with these formats: (ulaw)
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:26358 handle_request_invite: Checking SIP call limits for device test_105
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:6778 update_call_counter: Updating call counter for incoming call
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.212' into...
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.212' and port ''.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.212' into...
> [May 11 13:16:15] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.212' and port ''.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:25823 handle_request_invite_st: Incoming INVITE with 'timer' option supported
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:25833 handle_request_invite_st: INVITE also has "Session-Expires" header.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:29914 parse_session_expires: Session-Expires: 3600
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:29930 parse_session_expires: Refresher: UAS
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:25845 handle_request_invite_st: INVITE also has "Min-SE" header.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:29884 parse_minse: Received Min-SE: 90
> [May 11 13:16:15] DEBUG[9873]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:8181 sip_new: *** Our native formats are (ulaw)
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:8182 sip_new: *** Joint capabilities are (ulaw)
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:8183 sip_new: *** Our capabilities are (ulaw)
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:8184 sip_new: *** AST_CODEC_CHOOSE formats are ulaw
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:8217 sip_new: This channel will not be able to handle video.
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:26562 handle_request_invite: SIP/test_105-00000002: New call is still down.... Trying...
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:3764 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.101:5062
> [May 11 13:16:15] DEBUG[9884]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - test_105
> [May 11 13:16:15] DEBUG[9884]: chan_sip.c:30304 sip_devicestate: Checking device state for peer test_105
> [May 11 13:16:15] DEBUG[9884]: devicestate.c:474 do_state_change: Changing state for SIP/test_105 - state 5 (Unavailable)
> [May 11 13:16:15] DEBUG[9952][C-00000002]: pbx.c:2875 pbx_extension_helper: Launching 'ConfBridge'
> -- Executing [765 at sipin:1] ConfBridge("SIP/test_105-00000002", "1,,qsd-confbridge-1") in new stack
> [May 11 13:16:15] DEBUG[9884]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - test_105
> [May 11 13:16:15] DEBUG[9884]: chan_sip.c:30304 sip_devicestate: Checking device state for peer test_105
> [May 11 13:16:15] DEBUG[9884]: devicestate.c:474 do_state_change: Changing state for SIP/test_105 - state 5 (Unavailable)
> [May 11 13:16:15] DEBUG[9952][C-00000002]: chan_sip.c:7423 sip_answer: SIP answering channel: SIP/test_105-00000002
> [May 11 13:16:15] DEBUG[9952][C-00000002]: res_rtp_asterisk.c:3102 ast_rtp_update_source: Setting the marker bit due to a source update
> [May 11 13:16:15] DEBUG[9952][C-00000002]: chan_sip.c:13508 add_sdp: ** Our capability: (ulaw) Video flag: True Text flag: True
> [May 11 13:16:15] DEBUG[9952][C-00000002]: chan_sip.c:13509 add_sdp: ** Our prefcodec: (nothing)
> [May 11 13:16:15] DEBUG[9952][C-00000002]: chan_sip.c:13679 add_sdp: -- Done with adding codecs to SDP
> [May 11 13:16:15] DEBUG[9952][C-00000002]: chan_sip.c:13704 add_sdp: Setting framing on incoming call: 0
> [May 11 13:16:15] DEBUG[9952][C-00000002]: chan_sip.c:13898 add_sdp: Done building SDP. Settling with this capability: (ulaw)
> [May 11 13:16:15] DEBUG[9952][C-00000002]: chan_sip.c:3764 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.101:5062
> [May 11 13:16:15] DEBUG[9916]: chan_sip.c:9451 __find_call: = Looking for Call ID: 59148e2e9e80-pemn84r9y5qv (Checking From) --From tag k1abg1u893 --To-tag as129bc13b
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:28778 handle_incoming: **** Received ACK (6) - Command in SIP ACK
> [May 11 13:16:15] DEBUG[9916][C-00000002]: chan_sip.c:4548 __sip_ack: Stopping retransmission on '59148e2e9e80-pemn84r9y5qv' of Response 2: Match Found
> [May 11 13:16:15] DEBUG[9916]: chan_sip.c:29841 __start_session_timer: Session timer started: 14 - 59148e2e9e80-pemn84r9y5qv 900000ms
> [May 11 13:16:15] DEBUG[9952][C-00000002]: res_rtp_asterisk.c:4220 ast_rtcp_interpret: Got RTCP report of 48 bytes
> [May 11 13:16:15] DEBUG[9930]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.101:56479' into...
> [May 11 13:16:15] DEBUG[9930]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.101' and port '56479'.
> [May 11 13:16:15] DEBUG[9930]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.212:17213' into...
> [May 11 13:16:15] DEBUG[9930]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.212' and port '17213'.
> [May 11 13:16:15] DEBUG[9952][C-00000002]: res_rtp_asterisk.c:4663 ast_rtp_read: 0x7f26300065d0 -- Probation learning mode pass with source address 192.168.1.101:56478
> > 0x7f26300065d0 -- Probation passed - setting RTP source address to 192.168.1.101:56478
> [May 11 13:16:15] DEBUG[9952][C-00000002]: app.c:1555 __ast_play_and_record: play_and_record: vm-rec-name, /var/spool/asterisk/confbridge/confbridge-name-1-1494519375.8, 'sln'
> [May 11 13:16:15] DEBUG[9952][C-00000002]: res_rtp_asterisk.c:3675 ast_rtp_write: Ooh, format changed from none to ulaw
> [May 11 13:16:15] DEBUG[9952][C-00000002]: channel.c:3478 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
> -- <SIP/test_105-00000002> Playing 'vm-rec-name.ulaw' (language 'en')
> [May 11 13:16:17] DEBUG[9916]: chan_sip.c:9451 __find_call: = Looking for Call ID: 59148e2e9e80-pemn84r9y5qv (Checking From) --From tag k1abg1u893 --To-tag as129bc13b
> [May 11 13:16:17] DEBUG[9916][C-00000002]: chan_sip.c:28778 handle_incoming: **** Received BYE (8) - Command in SIP BYE
> [May 11 13:16:17] DEBUG[9916][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.101:5062' into...
> [May 11 13:16:17] DEBUG[9916][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.101' and port '5062'.
> [May 11 13:16:17] DEBUG[9916][C-00000002]: chan_sip.c:3420 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 59148e2e9e80-pemn84r9y5qv
> [May 11 13:16:17] DEBUG[9916][C-00000002]: res_rtp_asterisk.c:5174 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f2630006180'
> [May 11 13:16:17] DEBUG[9916][C-00000002]: chan_sip.c:27385 handle_request_bye: Received bye, issuing owner hangup
> [May 11 13:16:17] DEBUG[9916][C-00000002]: chan_sip.c:3764 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.101:5062
> [May 11 13:16:17] DEBUG[9916]: chan_sip.c:29780 do_stop_session_timer: Session timer stopped: 14 - 59148e2e9e80-pemn84r9y5qv
> [May 11 13:16:17] DEBUG[9952][C-00000002]: channel.c:3478 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
> [May 11 13:16:17] DEBUG[9952][C-00000002]: channel.c:3478 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
> [May 11 13:16:17] DEBUG[9952][C-00000002]: app_confbridge.c:1422 join_conference_bridge: Trying to find conference bridge '1'
> [May 11 13:16:17] DEBUG[9952][C-00000002]: bridge.c:496 find_best_technology: Bridge technology native_dahdi does not have any capabilities we want.
> [May 11 13:16:17] DEBUG[9952][C-00000002]: bridge.c:496 find_best_technology: Bridge technology simple_bridge does not have any capabilities we want.
> [May 11 13:16:17] DEBUG[9952][C-00000002]: bridge.c:496 find_best_technology: Bridge technology native_rtp does not have any capabilities we want.
> [May 11 13:16:17] DEBUG[9952][C-00000002]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
> [May 11 13:16:17] DEBUG[9952][C-00000002]: bridge.c:515 find_best_technology: Chose bridge technology softmix
> [May 11 13:16:17] DEBUG[9952][C-00000002]: bridge.c:794 bridge_base_init: Bridge ca7af8c1-a75b-447b-8fd1-7a87d95e8497: calling softmix technology constructor
> [May 11 13:16:17] DEBUG[9952][C-00000002]: bridge.c:802 bridge_base_init: Bridge ca7af8c1-a75b-447b-8fd1-7a87d95e8497: calling softmix technology start
> [May 11 13:16:17] DEBUG[9953]: bridge_softmix.c:1100 softmix_mixing_thread: Bridge ca7af8c1-a75b-447b-8fd1-7a87d95e8497: starting mixing thread
> [May 11 13:16:17] DEBUG[9952][C-00000002]: bridge_roles.c:272 setup_bridge_role: Set role 'announcer'
> [May 11 13:16:17] DEBUG[9952][C-00000002]: app_confbridge.c:1367 alloc_playback_chan: Created announcer channel 'CBAnn/1-00000002;1' to conference bridge '1'
> [May 11 13:16:17] DEBUG[9952][C-00000002]: app_confbridge.c:1524 join_conference_bridge: Created conference '1' and linked to container.
> [May 11 13:16:17] DEBUG[9936]: app_queue.c:2482 device_state_cb: Device 'confbridge:1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
> [May 11 13:16:17] DEBUG[9952][C-00000002]: confbridge/conf_state.c:84 conf_change_state: Changing conference '1' state from EMPTY to SINGLE
> [May 11 13:16:17] DEBUG[9952][C-00000002]: app_confbridge.c:1145 conf_update_user_mute: User SIP/test_105-00000002 is unmuted: user:0 system:0.
> [May 11 13:16:17] DEBUG[9952][C-00000002]: confbridge/conf_state.c:84 conf_change_state: Changing conference '1' state from SINGLE to EMPTY
> [May 11 13:16:17] DEBUG[9936]: app_queue.c:2482 device_state_cb: Device 'confbridge:1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
> [May 11 13:16:17] DEBUG[9952][C-00000002]: pbx.c:4345 __ast_pbx_run: Spawn extension (sipin,765,1) exited non-zero on 'SIP/test_105-00000002'
> == Spawn extension (sipin, 765, 1) exited non-zero on 'SIP/test_105-00000002'
> [May 11 13:16:17] DEBUG[9952][C-00000002]: channel.c:2582 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/test_105-00000002'
> [May 11 13:16:17] DEBUG[9952][C-00000002]: channel.c:2731 ast_hangup: Hanging up channel 'SIP/test_105-00000002'
> [May 11 13:16:17] DEBUG[9952][C-00000002]: chan_sip.c:7165 sip_hangup: Hangup call SIP/test_105-00000002, SIP callid 59148e2e9e80-pemn84r9y5qv
> [May 11 13:16:17] DEBUG[9952][C-00000002]: res_rtp_asterisk.c:5174 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f2630006180'
> [May 11 13:16:17] DEBUG[9884]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - test_105
> [May 11 13:16:17] DEBUG[9884]: chan_sip.c:30304 sip_devicestate: Checking device state for peer test_105
> [May 11 13:16:17] DEBUG[9884]: devicestate.c:474 do_state_change: Changing state for SIP/test_105 - state 5 (Unavailable)
> [May 11 13:16:17] DEBUG[9885]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/test_105-00000002 - start 1494519375.018327 answer 1494519375.019971 end 1494519377.111862 dispo ANSWERED
> [May 11 13:16:17] DEBUG[9885]: cdr_radius.c:222 radius_log: Unable to create RADIUS record. CDR not recorded!
> [May 11 13:16:17] DEBUG[9885]: res_config_sqlite.c:827 cdr_handler: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"One Oh Five" <406667778888>','406667778888','765','sipin','SIP/test_105-00000002','ConfBridge','1,,qsd-confbridge-1','2017-05-11 13:16:15','2017-05-11 13:16:15','2017-05-11 13:16:17','2','2','ANSWERED','DOCUMENTATION','1494519375.8')
> [May 11 13:16:17] ERROR[9885]: res_config_sqlite.c:840 cdr_handler: attempt to write a readonly database
> [May 11 13:16:17] DEBUG[9955]: bridge_channel.c:2654 bridge_channel_internal_join: Bridge ca7af8c1-a75b-447b-8fd1-7a87d95e8497: 0xba9490(CBAnn/1-00000002;2) is joining
> [May 11 13:16:17] DEBUG[9955]: bridge_channel.c:2118 bridge_channel_internal_push_full: Bridge ca7af8c1-a75b-447b-8fd1-7a87d95e8497: pushing 0xba9490(CBAnn/1-00000002;2)
> [May 11 13:16:17] DEBUG[9955]: bridge_roles.c:272 setup_bridge_role: Set role 'announcer'
> -- Channel CBAnn/1-00000002;2 joined 'softmix' base-bridge <ca7af8c1-a75b-447b-8fd1-7a87d95e8497>
> [May 11 13:16:17] DEBUG[9955]: bridge.c:432 bridge_channel_complete_join: Bridge ca7af8c1-a75b-447b-8fd1-7a87d95e8497: 0xba9490(CBAnn/1-00000002;2) is joining softmix technology
> [May 11 13:16:17] DEBUG[9955]: dsp.c:499 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
> [May 11 13:16:17] DEBUG[9955]: dsp.c:499 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
> [May 11 13:16:17] DEBUG[9954]: app_confbridge.c:1027 destroy_conference_bridge: Destroying conference bridge '1'
> disasterisk*CLI> core show channels
> Channel Location State Application(Data)
> CBAnn/1-00000001;2 s at default:1 Up (None)
> CBAnn/1-00000001;1 s at default:1 Up (None)
> CBAnn/1-00000002;2 s at default:1 Up (None)
> CBAnn/1-00000002;1 s at default:1 Up (None)
> 4 active channels
> 0 active calls
> 3 calls processed
> [May 11 13:16:25] DEBUG[9916]: chan_sip.c:4372 __sip_autodestruct: Auto destroying SIP dialog '59148e22a350-4zmcg34qn0ss'
> [May 11 13:16:25] DEBUG[9916]: chan_sip.c:6600 sip_pvt_dtor: Destroying SIP dialog 59148e22a350-4zmcg34qn0ss
> [May 11 13:16:25] DEBUG[9916]: rtp_engine.c:397 instance_destructor: Destroyed RTP instance '0x7f263000a490'
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list