Trunk sequence and 487 Request terminated leads to fail over instead of end

dirk2358 · September 10, 2022, 4:09pm

Hi,

given is an outbound route with two trunks in trunk sequence. If an outgoing call to an offline mobile is processed, the provider terminates the call with 487.

FreePBX now tries the next configured trunk - which doesn’t make any sense, because the callee can’t be reachable via any other provider, too.

How can I prevent FreePBX using the fallback trunk if there is a 487?

The 487 message contains the additional header (Deutsche Telekom):

Reason: X.int;reasoncode=0x00000A03;add-info=05CC.0008.0006

or (Easybell)

Reason: SIP;cause=487;text="Request Terminated"

Thanks for any hints!
Dirk

david55 · September 10, 2022, 6:43pm

487 is not something with which a provider can voluntarily terminate the call. It should be the result of Asterisk issuing a CANCEL, in which case FreePBX is trying the alternative routing because of local timeout on the primary route, not because of a response it received.

There is another case, when there is an Expires header in the request, but I don’t believe Asterisk will do that, unless you manually add such a header.

Also, you haven’t said which channel driver, which might affect things.

dirk2358 · September 11, 2022, 5:52am

pjsip is used as channel driver.

No, asterisk doesn’t terminate the call - it’s terminated by the trunk provider (because the mobile provider terminates the call). And there isn’t any timeout, because the provider of the mobile places an announcement (in two speeches), telling the caller, that the mobile isn’t reachable and that the callee would be informed by SMS which is free of charge. After the announcement, the call is terminated by the mobile provider.

The SIP messages involved are (between asterisk and trunks):

[Trunk 1]
INVITE --->
100 Trying <---
183 Session Progress <---
183 Session Progress SDP (P-Early-Media (-> PEM)) <--- (-> that's the announcement)
PRACK -->
200 OK <--
487 Request terminated <--
ACK -->

[Trunk 2]
INVITE --->
100 Trying <---
183 Session Progress SDP <--- (-> that's the announcement)
487 Request terminated <--
ACK -->

One more thing:
Asterisk obviously can’t handle a call stopped by 487 through provider at all, because after the 487 Request terminated, it is sending to the internal caller 500 internal server error. I simplified the test by reducing the number of involved trunks to the second trunk only (w/o PEM involved and without fail over coming in). This is reproducible (asterisk 18.14)

david55 · September 11, 2022, 10:48am

You need to provide complete protocol logs (CLI: pjsip set logger on). It looks to me that is the PRACK that is receiving the 487, and the actual call has received 200, but I’d need the full logs to be sure of that. In that case the call has not been stopped, and will require a BYE to stop it.

You also need to provide verbose level 5 logging, from the full log. Higher levels may be subsequently needed.

There may be a bug, but I don’t think it is the one you thing it is.

I’d need to do more reading to see if this is the correct way of handling a final status/PRACK collision, as PRACK is not covered by the core SIP RFC.

It may be possible to work round this by disabling PRACK.

If the 200 relates to the PRACK, and the 487 to the INVITE, the provider is at fault.

The mobile operator terminating the call would result in 200 OK, as they start the call, followed by a BYE request from the provider, to terminate it. The mobile operator refusing the call could result in many different final statuses, e.g, 404, 480, 486, 503,…, but never 487,

david55 · September 11, 2022, 11:10am

RFC 3262 seems to require a 200 response to a PRACK that collides with a final response.

As already noted, RFC 3261 only permits 487 when the original request has been terminated as the result of CANCEL, BYE, or an expired Expires header in the original request, none of which seems to apply here.

Although some questions remain open, failing over seems to me to be exactly the right response when faced with a protocol violation.

dirk2358 · September 11, 2022, 1:50pm

The 500 internal server error is not related to the PRACK as it happens, too, without PRACK being involved (Trunk 2) and without fail over being involved (just a pretty trivial single call).

The 487 received by the trunk provider (here: easybell) is definitely related to the initial INVITE:

2022/09/11 08:02:27.607526 212.172.58.207:5061 -> 0.0.0.0:0
SIP/2.0 487 Request Terminated
Via: SIP/2.0/TLS x.x.x.x:38771;rport=38771;branch=z9hG4bKPjf90ddee7-2c65-49bb-9b23-9df831329444;alias;received=x.x.x.x
From: <sip:[email protected]>;tag=cd795429-8cdd-45f3-bb96-b8731eedf133
To: <sip:[email protected]>;tag=7893489E-631D79E9000D9BA5-11EE0700
Call-ID: da223052-9163-4c83-93e1-ca4007111305
CSeq: 20227 INVITE
Reason: SIP;cause=487;text="Request Terminated"
Content-Length: 0

All this happens during early media session:

Trace after 487 coming in:

<--- Received SIP response (481 bytes) from TLS:212.172.58.207:5061 --->
SIP/2.0 487 Request Terminated
Via: SIP/2.0/TLS x.x.x.x:38771;rport=38771;branch=z9hG4bKPjf90ddee7-2c65-49bb-9b23-9df831329444;alias;received=x.x.x.x
From: <sip:[email protected]>;tag=cd795429-8cdd-45f3-bb96-b8731eedf133
To: <sip:[email protected]>;tag=7893489E-631D79E9000D9BA5-11EE0700
Call-ID: da223052-9163-4c83-93e1-ca4007111305
CSeq: 20227 INVITE
Reason: SIP;cause=487;text="Request Terminated"
Content-Length: 0


[2022-09-11 08:02:27] DEBUG[2210]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '212.172.58.207:5061' into...
[2022-09-11 08:02:27] DEBUG[2210]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '212.172.58.207' and port '5061'.
[2022-09-11 08:02:27] DEBUG[2210]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.6.170:38771' into...
[2022-09-11 08:02:27] DEBUG[2210]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.6.170' and port '38771'.
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip/pjsip_distributor.c:503 distributor: Searching for serializer associated with dialog dlg0x7f31203ceff8 for Response msg 487/INVITE/cseq=20227 (rdata0x7f307c320f58)
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip/pjsip_distributor.c:511 distributor: Found serializer pjsip/outsess/easybellPJSIP-000001c8 associated with dialog dlg0x7f31203ceff8
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '212.172.58.207' into...
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '212.172.58.207' and port ''.
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.6.170:38771' into...
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.6.170' and port '38771'.
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '212.172.58.207:5061' into...
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '212.172.58.207' and port '5061'.
<--- Transmitting SIP request (480 bytes) to TLS:212.172.58.207:5061 --->
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/TLS x.x.x.x:38771;rport;branch=z9hG4bKPjf90ddee7-2c65-49bb-9b23-9df831329444;alias
From: <sip:[email protected]>;tag=cd795429-8cdd-45f3-bb96-b8731eedf133
To: <sip:[email protected]>;tag=7893489E-631D79E9000D9BA5-11EE0700
Call-ID: da223052-9163-4c83-93e1-ca4007111305
CSeq: 20227 ACK
Max-Forwards: 70
User-Agent: FPBX-15.0.23.17(18.14.0)
Content-Length:  0


[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4218 session_on_rx_response:  PJSIP/easybellPJSIP-00000263 Method: INVITE Status: 487
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4220 session_on_rx_response:  
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4645 session_inv_on_state_changed:  PJSIP/easybellPJSIP-00000263 Event: TSX_STATE  Inv State: DISCONNCTD
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4382 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4396 __print_debug_details: The state change pertains to the endpoint 'easybellPJSIP(PJSIP/easybellPJSIP-00000263)'
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4401 __print_debug_details: The inv session still has an invite_tsx (0x7f31203a6758)
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4416 __print_debug_details: There is no transaction involved in this state change
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4418 __print_debug_details: The current inv state is DISCONNCTD
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4671 session_inv_on_state_changed: PJSIP/easybellPJSIP-00000263: Source of transaction state change is RX_MSG
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4613 handle_incoming_before_media: PJSIP/easybellPJSIP-00000263: Received response
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4480 handle_incoming_response:  PJSIP/easybellPJSIP-00000263: Response is 487 Request Terminated
[2022-09-11 08:02:27] DEBUG[19410]: chan_pjsip.c:3177 chan_pjsip_incoming_response_update_cause:  PJSIP/easybellPJSIP-00000263: Status: 487
[2022-09-11 08:02:27] DEBUG[19410]: chan_pjsip.c:3198 chan_pjsip_incoming_response_update_cause:  PJSIP/easybellPJSIP-00000263
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4491 handle_incoming_response:  PJSIP/easybellPJSIP-00000263
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4718 session_inv_on_state_changed:  
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4763 session_inv_on_tsx_state_changed:  PJSIP/easybellPJSIP-00000263 TSX State: Completed  Inv State: DISCONNCTD
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4382 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4396 __print_debug_details: The state change pertains to the endpoint 'easybellPJSIP(PJSIP/easybellPJSIP-00000263)'
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4401 __print_debug_details: The inv session still has an invite_tsx (0x7f31203a6758)
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4407 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f31203a6758
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4411 __print_debug_details: The current transaction state is Completed
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4413 __print_debug_details: The transaction state change event is RX_MSG
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4418 __print_debug_details: The current inv state is DISCONNCTD
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4784 session_inv_on_tsx_state_changed:  Disconnected
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4195 session_on_tsx_state:  (null session) TSX State: Completed  Inv State: DISCONNCTD
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4203 session_on_tsx_state:  
[2022-09-11 08:02:27] DEBUG[19410]: chan_pjsip.c:2990 chan_pjsip_session_end:  PJSIP/easybellPJSIP-00000263
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: chan_pjsip.c:1628 chan_pjsip_indicate:  PJSIP/100-00000262: Indicated Private Cause Code
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: chan_pjsip.c:1858 chan_pjsip_indicate:  PJSIP/100-00000262
[2022-09-11 08:02:27] DEBUG[19410]: chan_pjsip.c:3007 chan_pjsip_session_end:  
[2022-09-11 08:02:27] DEBUG[2198]: cdr.c:1483 cdr_object_finalize: Finalized CDR for PJSIP/100-00000262 - start 1662876137.610312 answer 0.000000 end 1662876147.611832 dur 10.001 bill 1662876147.611 dispo NO ANSWER
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: channel.c:2550 ast_hangup: Channel 0x7f309c001c10 'PJSIP/easybellPJSIP-00000263' hanging up.  Refs: 2
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: chan_pjsip.c:2537 chan_pjsip_hangup:  PJSIP/easybellPJSIP-00000263
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: chan_pjsip.c:2555 chan_pjsip_hangup:  Cause: 500
  == Everyone is busy/congested at this time (1:0/0/1)
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_dial.c:1328 wait_for_answer:  PJSIP/100-00000262: No outgoing channels available
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_dial.c:3475 dial_exec_full: Exiting with DIALSTATUS=CHANUNAVAIL.
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_dial.c:3506 dial_exec_full:  PJSIP/100-00000262: Done
[2022-09-11 08:02:27] DEBUG[19410]: chan_pjsip.c:2504 hangup:  PJSIP/easybellPJSIP-00000263
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:3470 ast_sip_session_terminate:  PJSIP/easybellPJSIP-00000263 Response 500
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_macro.c:482 _macro_exec: Executed application: Dial
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2879 dtls_srtp_stop_timeout_timer: (0x7f312404f1a0) DTLS srtp - stopped timeout timer'
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2879 dtls_srtp_stop_timeout_timer: (0x7f312404f1a0) DTLS srtp - stopped timeout timer'
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2281 ast_rtp_dtls_stop: (0x7f312404f1a0) DTLS stop
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2879 dtls_srtp_stop_timeout_timer: (0x7f312404f1a0) DTLS srtp - stopped timeout timer'
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2879 dtls_srtp_stop_timeout_timer: (0x7f312404f1a0) DTLS srtp - stopped timeout timer'
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:4012 rtp_deallocate_transport: (0x7f312404f1a0) ICE RTP transport deallocating
[2022-09-11 08:02:27] DEBUG[19410]: rtp_engine.c:455 instance_destructor: Destroyed RTP instance '0x7f312404f1a0'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'CHANUNAVAIL'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '127'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'NoOp'
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:3542 ast_sip_session_terminate:  
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:2926 session_destructor: easybellPJSIP: Destroying SIP session
    -- Executing [s@macro-dialout-trunk:28] NoOp("PJSIP/100-00000262", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 127") in new stack
[2022-09-11 08:02:27] DEBUG[19410]: channel.c:2196 ast_channel_destructor: Channel 0x7f309c001c10 'PJSIP/easybellPJSIP-00000263' destroying
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_macro.c:482 _macro_exec: Executed application: Noop
[2022-09-11 08:02:27] DEBUG[2198]: cdr.c:1483 cdr_object_finalize: Finalized CDR for PJSIP/easybellPJSIP-00000263 - start 1662876137.729817 answer 0.000000 end 1662876147.613289 dur 9.883 bill 1662876147.613 dispo NO ANSWER
[2022-09-11 08:02:27] DEBUG[2198]: cdr.c:1314 cdr_object_create_public_records: CDR for PJSIP/easybellPJSIP-00000263 is dialed and has no Party B; discarding
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'ARG4' is 'off'
[2022-09-11 08:02:27] DEBUG[19410]: stasis.c:443 topic_dtor: Destroying topic. name: channel:1662876137.611, detail: 
[2022-09-11 08:02:27] DEBUG[19410]: stasis.c:451 topic_dtor: Topic 'channel:1662876137.611': 0x7f309c00e420 destroyed
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:874 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'CHANUNAVAIL'
[2022-09-11 08:02:27] DEBUG[19410]: channel_internal_api.c:703 ast_channel_nativeformats_set:  <initializing>: MultistreamFormats: (nothing)
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'GotoIf'
[2022-09-11 08:02:27] DEBUG[19410]: channel_internal_api.c:713 ast_channel_nativeformats_set:  Channel is being initialized or destroyed
    -- Executing [s@macro-dialout-trunk:29] GotoIf("PJSIP/100-00000262", "0?continue,1:s-CHANUNAVAIL,1") in new stack
[2022-09-11 08:02:27] DEBUG[19410]: chan_pjsip.c:2528 hangup:  
[2022-09-11 08:02:27] DEBUG[2096]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for PJSIP - easybellPJSIP
    -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-09-11 08:02:27] DEBUG[2096]: devicestate.c:466 do_state_change: Changing state for PJSIP/easybellPJSIP - state 1 (Not in use)
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '127'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:798 pbx_substitute_variables_helper_full_location: Function ISNULL(127) result is '0'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:874 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '127'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:798 pbx_substitute_variables_helper_full_location: Function IF(0?0:127) result is '127'
[2022-09-11 08:02:27] DEBUG[2202]: res_odbc.c:965 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f3118013a90 from class 'asteriskcdrdb'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'Set'
    -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set("PJSIP/100-00000262", "RC=127") in new stack
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'RC' is '127'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'Goto'
    -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto("PJSIP/100-00000262", "127,1") in new stack
    -- Goto (macro-dialout-trunk,127,1)
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_macro.c:482 _macro_exec: Executed application: Goto
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'Goto'
    -- Executing [127@macro-dialout-trunk:1] Goto("PJSIP/100-00000262", "continue,1") in new stack
    -- Goto (macro-dialout-trunk,continue,1)
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_macro.c:482 _macro_exec: Executed application: Goto
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'CHANUNAVAIL'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '127'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'NoOp'
    -- Executing [continue@macro-dialout-trunk:1] NoOp("PJSIP/100-00000262", "TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 127 - failing through to other trunks") in new stack
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_macro.c:482 _macro_exec: Executed application: Noop
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'AMPUSER' is '100'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:874 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'AMPUSER' is '100'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [continue@macro-dialout-trunk:2] ExecIf("PJSIP/100-00000262", "1?Set(CALLERID(number)=100)") in new stack
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:510 ast_str_substitute_variables_full2: Evaluating 'AMPUSER' (from 'AMPUSER}"!="" ' len 7)
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'AMPUSER' is '100'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:564 ast_str_substitute_variables_full2: Variable AMPUSER result is '100' from channel
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:631 ast_str_substitute_variables_full2: Expression result is '1'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:510 ast_str_substitute_variables_full2: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7)
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'AMPUSER' is '100'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:564 ast_str_substitute_variables_full2: Variable AMPUSER result is '100' from channel
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx_variables.c:383 ast_str_retrieve_variable: Result of 'ROUTE_CIDSAVE' is '"C610IP" <100>'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'Set'
    -- Executing [0151...@from-internal:15] Set("PJSIP/100-00000262", "CALLERID(all)="C610IP" <100>") in new stack
[2022-09-11 08:02:27] DEBUG[2042]: threadpool.c:537 grow: Increasing threadpool stasis/pool's size by 1
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4763 session_inv_on_tsx_state_changed:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4382 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4394 __print_debug_details: inv_session 0x7f312402ca78 has no ast session
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4404 __print_debug_details: The inv session does NOT have an invite_tsx
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4407 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f31203a6758
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4411 __print_debug_details: The current transaction state is Terminated
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4413 __print_debug_details: The transaction state change event is TIMER
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4418 __print_debug_details: The current inv state is DISCONNCTD
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4774 session_inv_on_tsx_state_changed:  Session ended
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4195 session_on_tsx_state:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[2022-09-11 08:02:27] DEBUG[2210]: res_pjsip_session.c:4203 session_on_tsx_state:  
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'Set'
    -- Executing [0151...@from-internal:16] Set("PJSIP/100-00000262", "_KEEPCID=TRUE") in new stack
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'Goto'
    -- Executing [0151...@from-internal:17] Goto("PJSIP/100-00000262", "app-blackhole,hangup,1") in new stack
    -- Goto (app-blackhole,hangup,1)
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'NoOp'
    -- Executing [hangup@app-blackhole:1] NoOp("PJSIP/100-00000262", "Blackhole Dest: Hangup") in new stack
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:2939 pbx_extension_helper: Launching 'Hangup'
    -- Executing [hangup@app-blackhole:2] Hangup("PJSIP/100-00000262", "") in new stack
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: channel.c:2459 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'PJSIP/100-00000262'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: pbx.c:4438 __ast_pbx_run: Spawn extension (app-blackhole,hangup,2) exited non-zero on 'PJSIP/100-00000262'
  == Spawn extension (app-blackhole, hangup, 2) exited non-zero on 'PJSIP/100-00000262'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: channel.c:2459 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/100-00000262'
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: channel.c:2550 ast_hangup: Channel 0x7f312402d5f0 'PJSIP/100-00000262' hanging up.  Refs: 2
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: chan_pjsip.c:2537 chan_pjsip_hangup:  PJSIP/100-00000262
[2022-09-11 08:02:27] DEBUG[19539][C-00000136]: chan_pjsip.c:2555 chan_pjsip_hangup:  Cause: 500
[2022-09-11 08:02:27] DEBUG[19410]: chan_pjsip.c:2504 hangup:  PJSIP/100-00000262
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:3470 ast_sip_session_terminate:  PJSIP/100-00000262 Response 500
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2879 dtls_srtp_stop_timeout_timer: (0x7f3124038b40) DTLS srtp - stopped timeout timer'
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2879 dtls_srtp_stop_timeout_timer: (0x7f3124038b40) DTLS srtp - stopped timeout timer'
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2281 ast_rtp_dtls_stop: (0x7f3124038b40) DTLS stop
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2879 dtls_srtp_stop_timeout_timer: (0x7f3124038b40) DTLS srtp - stopped timeout timer'
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:2879 dtls_srtp_stop_timeout_timer: (0x7f3124038b40) DTLS srtp - stopped timeout timer'
[2022-09-11 08:02:27] DEBUG[19410]: res_rtp_asterisk.c:4012 rtp_deallocate_transport: (0x7f3124038b40) ICE RTP transport deallocating
[2022-09-11 08:02:27] DEBUG[19410]: rtp_engine.c:455 instance_destructor: Destroyed RTP instance '0x7f3124038b40'
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4531 handle_outgoing_response:  PJSIP/100-00000262: Method is INVITE, Response is 500 Server Internal Error
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_session.c:4547 handle_outgoing_response:  PJSIP/100-00000262
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip/pjsip_message_filter.c:250 filter_on_tx_message: Transport is type listener, transport port 5060 - listener port is: 5060
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.6.173' into...
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.6.173' and port ''.
[2022-09-11 08:02:27] DEBUG[19410]: res_pjsip_nat.c:429 process_nat: Request is being sent to local address, skipping NAT manipulation
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.6.170:5060' into...
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.6.170' and port '5060'.
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.6.173:60520' into...
[2022-09-11 08:02:27] DEBUG[19410]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.6.173' and port '60520'.
<--- Transmitting SIP response (541 bytes) to TCP:192.168.6.173:60520 --->
SIP/2.0 500 Server Internal Error
Via: SIP/2.0/TCP 192.168.6.173:60520;rport=60520;received=192.168.6.173;branch=z9hG4bK3dcc52d22fb38357d6ed07f385775a50
Call-ID: 1843743134@192_168_6_173
From: "Home" <sip:[email protected]>;tag=2873216681
To: <sip:[email protected];user=phone>;tag=0d2d2b77-a604-4940-a0d3-f18cbd7601fd
CSeq: 3 INVITE
Server: FPBX-15.0.23.17(18.14.0)
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Reason: Q.850;cause=127
Content-Length:  0

david55 · September 11, 2022, 1:55pm

Definitely a protocol violation by the provider.

dirk2358 · September 11, 2022, 2:09pm

Thanks for your estimation - I’ll try to get some information from the provider.

david55 · September 11, 2022, 6:24pm

You should point the provider to RFC 3261, section 21.4.25, which defines the 487 response, and to the first list item in the second paragraphs of section 13.3.1, which is the only other circumstance in which 487 is valid, and also point out that Asterisk doesn’t use Expires on INVITEs. (This second one is belt and braces as the UAC is expected to send a cancel at the timeout point, as well.)

dirk2358 · September 12, 2022, 8:41am

This wouldn’t make any sense anyway at all. How long should the expire time be? At which point should it start?
There is early media going on - how should one know when it’s over?

david55 · September 12, 2022, 11:17am

The expire time would be the timeout in the Dial application call, as that is when it sends the CANCEL. However the point was that, as Asterisk doesn’t use this header in INVITEs, the only valid reasons for 487 are that Asterisk has sent CANCEL (or during a Re-INVITE, BYE), which also isn’t happening.

system · October 13, 2022, 11:17am

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.