Vieri Di Paola
2020-Jun-08 10:51 UTC
[asterisk-users] pjsip extensions rings but call drop on answer
Hi,
I created an IAX2 trunk between my old Asterisk 1.4 server (A) and my
new one with v. 16.10.0 (B).
The trunk seems to be up, and the calls are initiated, eg. an
extension from A can dial an extension in B which rings.
However, as soon as the extension in B answers, the call is terminated.
This is what I see in the console of B:
-- Called PJSIP/4053
-- PJSIP/4053-00000002 is ringing
-- PJSIP/4053-00000002 is ringing
-- No one is available to answer at this time (1:0/0/0)
-- Executing [4053 at custom-newsystem:4]
Hangup("IAX2/migration-8417", "") in new stack
I don't know why I'm getting "No one is available to answer at this
time".
On B:
# asterisk -rx "iax2 show peer migration"
* Name : migration
Description :
Secret : <Set>
Context : custom-newsystem
Parking lot :
Mailbox :
Dynamic : No
Callnum limit: 0
Calltoken req: No
Trunk : No
Encryption : No
Callerid : "" <>
Expire : -1
ACL : Yes
Addr->IP : 10.215.147.115 Port 4569
Defaddr->IP : (null) Port (null)
Username : interbox
Codecs :
(g723|gsm|ulaw|alaw|g726aal2|adpcm|slin|lpc10|g729|speex|ilbc|g726|g722|siren7|siren14|slin16|h264|vp8|opus)
Codec Order :
(ulaw|alaw|siren14|siren7|g722|slin16|slin|g726|g726aal2|adpcm|gsm|ilbc|speex|lpc10|g729|g723|opus|vp8|h264)
Status : OK (3 ms)
Qualify : every 60000ms when OK, every 10000ms when UNREACHABLE
(sample smoothing Off)
Asterisk ending (0).
Still on B, my extensions.conf contains:
[custom-newsystem]
exten => _XXXX,hint,PJSIP/${EXTEN}
exten => _XXXX,1,Answer()
same => n,NoOp(Old system caller ${CALLERID(all)} is calling ${EXTEN})
same => n,Dial(PJSIP/${EXTEN})
same => n,Hangup()
Finally, on B I see this in the Asterisk log:
[Jun 8 12:28:09] DEBUG[4607][C-00000003] pbx_variables.c: Result of
'EXTEN' is '4053'
[Jun 8 12:28:09] DEBUG[4607][C-00000003] pbx.c: Launching 'Dial'
[Jun 8 12:28:09] VERBOSE[4607][C-00000003] pbx.c: Executing
[4053 at custom-newsystem:3] Dial("IAX2/migration-8417",
"PJSIP/4053") in
new stack
[Jun 8 12:28:09] DEBUG[4180] config.c: extract double from [3.0] in
[-inf, inf] gives [3.000000](0)
[Jun 8 12:28:09] DEBUG[4180] config.c: extract uint from [0] in [0,
4294967295] gives [0](0)
[Jun 8 12:28:09] DEBUG[4180] config.c: extract double from [3.000000]
in [-inf, inf] gives [3.000000](0)
[Jun 8 12:28:09] DEBUG[4180] config.c: extract uint from [0] in [0,
4294967295] gives [0](0)
[Jun 8 12:28:09] DEBUG[4180] config.c: extract uint from [0] in [0,
86400] gives [0](0)
[Jun 8 12:28:09] DEBUG[4607][C-00000003] stasis.c: Creating topic.
name: channel:1591612089.24, detail:
[Jun 8 12:28:09] DEBUG[4607][C-00000003] stasis.c: Topic
'channel:1591612089.24': 0x7f056000e050 created
[Jun 8 12:28:09] DEBUG[4607][C-00000003] stasis.c: Creating topic.
name: cache:48/channel:1591612089.24, detail:
[Jun 8 12:28:09] DEBUG[4607][C-00000003] stasis.c: Topic
'cache:48/channel:1591612089.24': 0x7f056000dde0 created
[Jun 8 12:28:09] DEBUG[4607][C-00000003] channel.c: Channel
0x7f056000ac40 'PJSIP/4053-00000002' allocated
[Jun 8 12:28:09] DEBUG[4607][C-00000003] rtp_engine.c: Can't find
native functions for channel 'IAX2/migration-8417'
[Jun 8 12:28:09] DEBUG[4180] rtp_engine.c: Using engine 'asterisk'
for RTP instance '0x7f05780618e0'
[Jun 8 12:28:09] VERBOSE[4607][C-00000003] app_dial.c: Called PJSIP/4053
[Jun 8 12:28:09] DEBUG[4180] res_rtp_asterisk.c: Allocated port 31930
for RTP instance '0x7f05780618e0'
[Jun 8 12:28:09] DEBUG[4180] res_rtp_asterisk.c: Creating ICE session
[::]:31930 (31930) for RTP instance '0x7f05780618e0'
[Jun 8 12:28:09] DEBUG[4607][C-00000003] channel.c: Channel
PJSIP/4053-00000002 setting read format path: ulaw -> ulaw
[Jun 8 12:28:09] DEBUG[4607][C-00000003] channel.c: Channel
IAX2/migration-8417 setting write format path: ulaw -> ulaw
[Jun 8 12:28:09] DEBUG[4607][C-00000003] channel.c: Channel
IAX2/migration-8417 setting read format path: ulaw -> ulaw
[Jun 8 12:28:09] DEBUG[4607][C-00000003] channel.c: Channel
PJSIP/4053-00000002 setting write format path: ulaw -> ulaw
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: Splitting '192.168.228.1'
into...
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: ...host '192.168.228.1' and
port ''.
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: Splitting '192.168.101.2'
into...
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: ...host '192.168.101.2' and
port ''.
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: Splitting '10.215.144.92'
into...
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: ...host '10.215.144.92' and
port ''.
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: Splitting '172.16.0.2' into...
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: ...host '172.16.0.2' and port
''.
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: Splitting '192.168.100.2'
into...
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: ...host '192.168.100.2' and
port ''.
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: Splitting '192.168.92.2'
into...
[Jun 8 12:28:09] DEBUG[4199] chan_iax2.c: Callno 8417: Blocked
receiving control frame 20.
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: ...host '192.168.92.2' and
port ''.
[Jun 8 12:28:09] DEBUG[4199] chan_iax2.c: Callno 8417: Blocked
receiving control frame 20.
[Jun 8 12:28:09] DEBUG[4180] rtp_engine.c: RTP instance
'0x7f05780618e0' is setup and ready to go
[Jun 8 12:28:09] DEBUG[4180] res_rtp_asterisk.c: Resetting ICE for
RTP instance '0x7f05780618e0'
[Jun 8 12:28:09] DEBUG[4180] res_rtp_asterisk.c: Nevermind. ICE isn't
ready for a reset
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: Splitting 'asterisk2' into...
[Jun 8 12:28:09] DEBUG[4180] netsock2.c: ...host 'asterisk2' and port
''.
[Jun 8 12:28:09] DEBUG[4180] res_rtp_asterisk.c: Setup RTCP on RTP
instance '0x7f05780618e0'
[Jun 8 12:28:09] DEBUG[4180] res_srtp.c: local_key64
2Rbo7TRiuRAnS0IYJeSn0ELEYAVnkOVCUwou7pxO len 40
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_sdp_rtp.c: Stream msid:
0x7f0578077610 audio 23eb03ca-f0ee-406a-b7cd-5fb19fc33fa2
ddca7927-ff8d-45ab-a61f-9474f8b7a9df
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: Method is INVITE
[Jun 8 12:28:09] DEBUG[4180] res_pjsip/pjsip_resolver.c: Performing
SIP DNS resolution of target '10.215.144.48'
[Jun 8 12:28:09] DEBUG[4180] res_pjsip/pjsip_resolver.c: Transport
type for target '10.215.144.48' is 'ws'
[Jun 8 12:28:09] DEBUG[4180] res_pjsip/pjsip_resolver.c: Target
'10.215.144.48' is an IP address, skipping resolution
[Jun 8 12:28:09] DEBUG[4607][C-00000003] chan_iax2.c: Callno 8417:
Config blocked sending control frame 22.
[Jun 8 12:28:09] DEBUG[4180] res_http_websocket.c: Writing websocket
text frame, length 2161
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: Function
session_inv_on_state_changed called on event TSX_STATE
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The state change
pertains to the endpoint '4053(PJSIP/4053-00000002)'
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The inv session
still has an invite_tsx (0x7f0570019af8)
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: There is no
transaction involved in this state change
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The current inv
state is CALLING
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: Source of
transaction state change is TX_MSG
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: Function
session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The state change
pertains to the endpoint '4053(PJSIP/4053-00000002)'
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The inv session
still has an invite_tsx (0x7f0570019af8)
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The UAC INVITE
transaction involved in this state change is 0x7f0570019af8
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The current
transaction state is Calling
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The transaction
state change event is TX_MSG
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The current inv
state is CALLING
[Jun 8 12:28:09] DEBUG[4511] threadpool.c: Worker thread idle timeout
reached. Dying.
[Jun 8 12:28:09] DEBUG[4152] threadpool.c: Destroying worker thread 13
[Jun 8 12:28:09] DEBUG[4180] res_pjsip/pjsip_distributor.c: Searching
for serializer associated with dialog dlg0x7f0578069118 for Response
msg 100/INVITE/cseq=30101 (rdata0x7f057801c9e0)
[Jun 8 12:28:09] DEBUG[4180] res_pjsip/pjsip_distributor.c: Found
serializer pjsip/outsess/4053-00000077 associated with dialog
dlg0x7f0578069118
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: Function
session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The state change
pertains to the endpoint '4053(PJSIP/4053-00000002)'
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The inv session
still has an invite_tsx (0x7f0570019af8)
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The UAC INVITE
transaction involved in this state change is 0x7f0570019af8
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The current
transaction state is Proceeding
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The transaction
state change event is RX_MSG
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: The current inv
state is CALLING
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: Received response
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_session.c: Response is 100 Trying
[Jun 8 12:28:09] DEBUG[4180] res_pjsip_transport_websocket.c:
Response msg 180/INVITE/cseq=30101 (rdata0x7f057801c9e0) re-writing
Contact URI from 192.0.2.235:0;transport=wss to
10.215.144.48:64842;transport=ws
[Jun 8 12:28:09] DEBUG[4180] res_pjsip/pjsip_distributor.c: Searching
for serializer associated with dialog dlg0x7f0578069118 for Response
msg 180/INVITE/cseq=30101 (rdata0x7f057801c9e0)
[Jun 8 12:28:09] DEBUG[4180] res_pjsip/pjsip_distributor.c: Found
serializer pjsip/outsess/4053-00000077 associated with dialog
dlg0x7f0578069118
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_transport_websocket.c:
Response msg 180/INVITE/cseq=30101 (rdata0x7f057808bd18) re-writing
Contact URI from 10.215.144.48:64842;transport=ws to
10.215.144.48:64842;transport=ws
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: Function
session_inv_on_state_changed called on event TSX_STATE
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: The state change
pertains to the endpoint '4053(PJSIP/4053-00000002)'
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: The inv session
still has an invite_tsx (0x7f0570019af8)
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: There is no
transaction involved in this state change
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: The current inv
state is EARLY
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: Source of
transaction state change is RX_MSG
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: Received response
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: Response is 180 Ringing
[Jun 8 12:28:09] DEBUG[4164] devicestate.c: No provider found,
checking channel drivers for PJSIP - 4053
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: Function
session_inv_on_tsx_state_changed called on event TSX_STATE
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: The state change
pertains to the endpoint '4053(PJSIP/4053-00000002)'
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: The inv session
still has an invite_tsx (0x7f0570019af8)
[Jun 8 12:28:09] DEBUG[4181] res_pjsip_session.c: The UAC INVITE
transaction involved in this state change is 0x7f0570019af8
There is a firewall in the middle, but all ports and protocols are allowed.
Any ideas?
Vieri
Maybe Matching Threads
Wisdom of the Ancients
