I have a strange problem. My provider is registered within ASTPP and my fusion PBX should route external calls through ASTPP and then to the provider.
If I dial a DDI from outside the call is routed from ASTPP to FusionPBX sucessfully, however it then fails at Fusion with the following:
[INFO] mod_dptools.c:3436 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
[NOTICE] switch_core_state_machine.c:385 sofia/internal/1001@test.vc.co.uk has executed the last dialplan instruction, hanging up.
I also get the same error on FusionPBX if I make a call the other way, from FusionPBX softclient to external number however using ASTPP on it's own, I don't get any error and routing works, so it's some issue with the bridge between FPBX & ASTPP
Looking in a bit more detail, the softclient returns a 400 error, and if I look at this I get the following:
------------------------------------------------------------------------
INVITE sip:07517067999@88.215.54.139 SIP/2.0
Via: SIP/2.0/UDP 51.145.6.167;rport;branch=z9hG4bK12QZQUgm1t0jc
Max-Forwards: 68
From: "James Z" <sip:test@88.215.54.139>;tag=1N8BDe089cerc
To: <sip:07517067999@88.215.54.139>
Call-ID: f79d9d4f-af00-1237-59a5-000d3a0b4376
CSeq: 741932 INVITE
Contact: <sip:gw+Gamma-testing-GW@51.145.6.167:5060;transport=udp;gw=Gamma-testing-GW>
User-Agent: ASTPP
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 244
Remote-Party-ID: "James Z" <sip:01999236390 @88.215.54.139>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1550561898 1550561899 IN IP4 51.145.6.167
s=FreeSWITCH
c=IN IP4 51.145.6.167
t=0 0
m=audio 29550 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2019-02-19 15:50:48.401118 [DEBUG] sofia.c:7084 Channel sofia/default/07517067999 entering state [calling][0]
recv 309 bytes from udp/[88.215.54.139]:5060 at 15:50:48.415342:
------------------------------------------------------------------------
SIP/2.0 400 Bad Request
Via: SIP/2.0/UDP 51.145.6.167;rport;branch=z9hG4bK12QZQUgm1t0jc
From: "James Z" <sip:test@88.215.54.139>;tag=1N8BDe089cerc
Call-ID: f79d9d4f-af00-1237-59a5-000d3a0b4376
CSeq: 741932 INVITE
To: <sip:07517067999@88.215.54.139>;tag=3759580248-1855223889
Content-Length: 0
------------------------------------------------------------------------
send 342 bytes to udp/[88.215.54.139]:5060 at 15:50:48.415419:
------------------------------------------------------------------------
ACK sip:07517067999@88.215.54.139 SIP/2.0
Via: SIP/2.0/UDP 51.145.6.167;rport;branch=z9hG4bK12QZQUgm1t0jc
Max-Forwards: 68
From: "James Z" <sip:test@88.215.54.139>;tag=1N8BDe089cerc
To: <sip:07517067999@88.215.54.139>;tag=3759580248-1855223889
Call-ID: f79d9d4f-af00-1237-59a5-000d3a0b4376
CSeq: 741932 ACK
Content-Length: 0
------------------------------------------------------------------------
2019-02-19 15:50:48.401118 [DEBUG] sofia.c:7084 Channel sofia/default/07517067999 entering state [terminated][400]
2019-02-19 15:50:48.401118 [NOTICE] sofia.c:8273 Hangup sofia/default/07517067999 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:584 (sofia/default/07517067999) Running State Change CS_HANGUP (Cur 2 Tot 69)
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:850 (sofia/default/07517067999) Callstate Change DOWN -> HANGUP
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:852 (sofia/default/07517067999) State HANGUP
2019-02-19 15:50:48.401118 [DEBUG] mod_sofia.c:438 Channel sofia/default/07517067999 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:60 sofia/default/07517067999 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:852 (sofia/default/07517067999) State HANGUP going to sleep
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:619 (sofia/default/07517067999) State Change CS_HANGUP -> CS_REPORTING
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:584 (sofia/default/07517067999) Running State Change CS_REPORTING (Cur 2 Tot 69)
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:938 (sofia/default/07517067999) State REPORTING
2019-02-19 15:50:48.401118 [INFO] mod_json_cdr.c:271 Process [38e8824b-2ba5-46a6-a10f-461614e34861.cdr.json]
2019-02-19 15:50:48.421120 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2019-02-19 15:50:48.421120 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.421120 [NOTICE] switch_channel.c:4844 Hangup sofia/default/1861342969@billingportal.vc.co.uk [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
2019-02-19 15:50:48.421120 [DEBUG] switch_core_session.c:2815 sofia/default/1861342969@billingportal.vc.co.uk skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-02-19 15:50:48.421120 [DEBUG] switch_core_session.c:2815 sofia/default/1861342969@billingportal.vc.co.uk skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:650 (sofia/default/1861342969@billingportal.vc.co.uk) State EXECUTE going to sleep
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:584 (sofia/default/1861342969@billingportal.vc.co.uk) Running State Change CS_HANGUP (Cur 2 Tot 69)
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:850 (sofia/default/1861342969@billingportal.vc.co.uk) Callstate Change RINGING -> HANGUP
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:852 (sofia/default/1861342969@billingportal.vc.co.uk) State HANGUP
2019-02-19 15:50:48.421120 [DEBUG] mod_sofia.c:432 sofia/default/1861342969@billingportal.vc.co.uk Overriding SIP cause 503 with 400 from the other leg
2019-02-19 15:50:48.421120 [DEBUG] mod_sofia.c:438 Channel sofia/default/1861342969@billingportal.vc.co.uk hanging up, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.421120 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 400
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:60 sofia/default/1861342969@billingportal.vc.co.uk Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:852 (sofia/default/1861342969@billingportal.vc.co.uk) State HANGUP going to sleep
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:619 (sofia/default/1861342969@billingportal.vc.co.uk) State Change CS_HANGUP -> CS_REPORTING
send 757 bytes to udp/[51.140.158.186]:5060 at 15:50:48.432329:
------------------------------------------------------------------------
SIP/2.0 400 Bad Request
Via: SIP/2.0/UDP 51.140.158.186;rport=5060;branch=z9hG4bKScF5BrUrgrZrQ
Max-Forwards: 69
From: "James Z" <sip:1861342969@billingportal.vc.co.uk>;tag=ye8Fy9FrDe7mj
To: <sip:07517067999@billingportal.vc.co.uk>;tag=0cFKBKF5c4Q5g
Call-ID: f7929fc5-af00-1237-668b-00224807a7cd
CSeq: 741932 INVITE
User-Agent: ASTPP
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Reason: Q.850;cause=41;text="NORMAL_TEMPORARY_FAILURE"
Content-Length: 0
------------------------------------------------------------------------
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:584 (sofia/default/1861342969@billingportal.vc.co.uk) Running State Change CS_REPORTING (Cur 2 Tot 69)
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:938 (sofia/default/1861342969@billingportal.vc.co.uk) State REPORTING
2019-02-19 15:50:48.421120 [INFO] mod_json_cdr.c:271 Process [e5d501c8-a8eb-4e93-9b19-c98b45c9c17a.cdr.json]
recv 378 bytes from udp/[51.140.158.186]:5060 at 15:50:48.435136:
------------------------------------------------------------------------
ACK sip:07517067999@billingportal.vc.co.uk SIP/2.0
Via: SIP/2.0/UDP 51.140.158.186;rport;branch=z9hG4bKScF5BrUrgrZrQ
Max-Forwards: 69
From: "James Z" <sip:1861342969@billingportal.vc.co.uk>;tag=ye8Fy9FrDe7mj
To: <sip:07517067999@billingportal.vc.co.uk>;tag=0cFKBKF5c4Q5g
Call-ID: f7929fc5-af00-1237-668b-00224807a7cd
CSeq: 741932 ACK
Content-Length: 0
------------------------------------------------------------------------
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:174 sofia/default/07517067999 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:938 (sofia/default/07517067999) State REPORTING going to sleep
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:610 (sofia/default/07517067999) State Change CS_REPORTING -> CS_DESTROY
I'm guessing it's something to do with the header or the Content-Length: 0 value?
Any ideas?
If I dial a DDI from outside the call is routed from ASTPP to FusionPBX sucessfully, however it then fails at Fusion with the following:
[INFO] mod_dptools.c:3436 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
[NOTICE] switch_core_state_machine.c:385 sofia/internal/1001@test.vc.co.uk has executed the last dialplan instruction, hanging up.
I also get the same error on FusionPBX if I make a call the other way, from FusionPBX softclient to external number however using ASTPP on it's own, I don't get any error and routing works, so it's some issue with the bridge between FPBX & ASTPP
Looking in a bit more detail, the softclient returns a 400 error, and if I look at this I get the following:
------------------------------------------------------------------------
INVITE sip:07517067999@88.215.54.139 SIP/2.0
Via: SIP/2.0/UDP 51.145.6.167;rport;branch=z9hG4bK12QZQUgm1t0jc
Max-Forwards: 68
From: "James Z" <sip:test@88.215.54.139>;tag=1N8BDe089cerc
To: <sip:07517067999@88.215.54.139>
Call-ID: f79d9d4f-af00-1237-59a5-000d3a0b4376
CSeq: 741932 INVITE
Contact: <sip:gw+Gamma-testing-GW@51.145.6.167:5060;transport=udp;gw=Gamma-testing-GW>
User-Agent: ASTPP
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 244
Remote-Party-ID: "James Z" <sip:01999236390 @88.215.54.139>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1550561898 1550561899 IN IP4 51.145.6.167
s=FreeSWITCH
c=IN IP4 51.145.6.167
t=0 0
m=audio 29550 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2019-02-19 15:50:48.401118 [DEBUG] sofia.c:7084 Channel sofia/default/07517067999 entering state [calling][0]
recv 309 bytes from udp/[88.215.54.139]:5060 at 15:50:48.415342:
------------------------------------------------------------------------
SIP/2.0 400 Bad Request
Via: SIP/2.0/UDP 51.145.6.167;rport;branch=z9hG4bK12QZQUgm1t0jc
From: "James Z" <sip:test@88.215.54.139>;tag=1N8BDe089cerc
Call-ID: f79d9d4f-af00-1237-59a5-000d3a0b4376
CSeq: 741932 INVITE
To: <sip:07517067999@88.215.54.139>;tag=3759580248-1855223889
Content-Length: 0
------------------------------------------------------------------------
send 342 bytes to udp/[88.215.54.139]:5060 at 15:50:48.415419:
------------------------------------------------------------------------
ACK sip:07517067999@88.215.54.139 SIP/2.0
Via: SIP/2.0/UDP 51.145.6.167;rport;branch=z9hG4bK12QZQUgm1t0jc
Max-Forwards: 68
From: "James Z" <sip:test@88.215.54.139>;tag=1N8BDe089cerc
To: <sip:07517067999@88.215.54.139>;tag=3759580248-1855223889
Call-ID: f79d9d4f-af00-1237-59a5-000d3a0b4376
CSeq: 741932 ACK
Content-Length: 0
------------------------------------------------------------------------
2019-02-19 15:50:48.401118 [DEBUG] sofia.c:7084 Channel sofia/default/07517067999 entering state [terminated][400]
2019-02-19 15:50:48.401118 [NOTICE] sofia.c:8273 Hangup sofia/default/07517067999 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:584 (sofia/default/07517067999) Running State Change CS_HANGUP (Cur 2 Tot 69)
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:850 (sofia/default/07517067999) Callstate Change DOWN -> HANGUP
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:852 (sofia/default/07517067999) State HANGUP
2019-02-19 15:50:48.401118 [DEBUG] mod_sofia.c:438 Channel sofia/default/07517067999 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:60 sofia/default/07517067999 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:852 (sofia/default/07517067999) State HANGUP going to sleep
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:619 (sofia/default/07517067999) State Change CS_HANGUP -> CS_REPORTING
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:584 (sofia/default/07517067999) Running State Change CS_REPORTING (Cur 2 Tot 69)
2019-02-19 15:50:48.401118 [DEBUG] switch_core_state_machine.c:938 (sofia/default/07517067999) State REPORTING
2019-02-19 15:50:48.401118 [INFO] mod_json_cdr.c:271 Process [38e8824b-2ba5-46a6-a10f-461614e34861.cdr.json]
2019-02-19 15:50:48.421120 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2019-02-19 15:50:48.421120 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.421120 [NOTICE] switch_channel.c:4844 Hangup sofia/default/1861342969@billingportal.vc.co.uk [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
2019-02-19 15:50:48.421120 [DEBUG] switch_core_session.c:2815 sofia/default/1861342969@billingportal.vc.co.uk skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-02-19 15:50:48.421120 [DEBUG] switch_core_session.c:2815 sofia/default/1861342969@billingportal.vc.co.uk skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:650 (sofia/default/1861342969@billingportal.vc.co.uk) State EXECUTE going to sleep
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:584 (sofia/default/1861342969@billingportal.vc.co.uk) Running State Change CS_HANGUP (Cur 2 Tot 69)
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:850 (sofia/default/1861342969@billingportal.vc.co.uk) Callstate Change RINGING -> HANGUP
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:852 (sofia/default/1861342969@billingportal.vc.co.uk) State HANGUP
2019-02-19 15:50:48.421120 [DEBUG] mod_sofia.c:432 sofia/default/1861342969@billingportal.vc.co.uk Overriding SIP cause 503 with 400 from the other leg
2019-02-19 15:50:48.421120 [DEBUG] mod_sofia.c:438 Channel sofia/default/1861342969@billingportal.vc.co.uk hanging up, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.421120 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 400
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:60 sofia/default/1861342969@billingportal.vc.co.uk Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:852 (sofia/default/1861342969@billingportal.vc.co.uk) State HANGUP going to sleep
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:619 (sofia/default/1861342969@billingportal.vc.co.uk) State Change CS_HANGUP -> CS_REPORTING
send 757 bytes to udp/[51.140.158.186]:5060 at 15:50:48.432329:
------------------------------------------------------------------------
SIP/2.0 400 Bad Request
Via: SIP/2.0/UDP 51.140.158.186;rport=5060;branch=z9hG4bKScF5BrUrgrZrQ
Max-Forwards: 69
From: "James Z" <sip:1861342969@billingportal.vc.co.uk>;tag=ye8Fy9FrDe7mj
To: <sip:07517067999@billingportal.vc.co.uk>;tag=0cFKBKF5c4Q5g
Call-ID: f7929fc5-af00-1237-668b-00224807a7cd
CSeq: 741932 INVITE
User-Agent: ASTPP
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Reason: Q.850;cause=41;text="NORMAL_TEMPORARY_FAILURE"
Content-Length: 0
------------------------------------------------------------------------
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:584 (sofia/default/1861342969@billingportal.vc.co.uk) Running State Change CS_REPORTING (Cur 2 Tot 69)
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:938 (sofia/default/1861342969@billingportal.vc.co.uk) State REPORTING
2019-02-19 15:50:48.421120 [INFO] mod_json_cdr.c:271 Process [e5d501c8-a8eb-4e93-9b19-c98b45c9c17a.cdr.json]
recv 378 bytes from udp/[51.140.158.186]:5060 at 15:50:48.435136:
------------------------------------------------------------------------
ACK sip:07517067999@billingportal.vc.co.uk SIP/2.0
Via: SIP/2.0/UDP 51.140.158.186;rport;branch=z9hG4bKScF5BrUrgrZrQ
Max-Forwards: 69
From: "James Z" <sip:1861342969@billingportal.vc.co.uk>;tag=ye8Fy9FrDe7mj
To: <sip:07517067999@billingportal.vc.co.uk>;tag=0cFKBKF5c4Q5g
Call-ID: f7929fc5-af00-1237-668b-00224807a7cd
CSeq: 741932 ACK
Content-Length: 0
------------------------------------------------------------------------
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:174 sofia/default/07517067999 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:938 (sofia/default/07517067999) State REPORTING going to sleep
2019-02-19 15:50:48.421120 [DEBUG] switch_core_state_machine.c:610 (sofia/default/07517067999) State Change CS_REPORTING -> CS_DESTROY
I'm guessing it's something to do with the header or the Content-Length: 0 value?
Any ideas?
