Pjsip Extensions Rings But Call Drop On Answer

Home » Asterisk Users » Pjsip Extensions Rings But Call Drop On Answer
Asterisk Users No Comments

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@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 :
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@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

—