INVITE with Replaces is rejected with error 603

Asterisk Asterisk SIP
1

Hello Everyone,

I’m experiencing an issue when Asterisk randomly rejects INVITE with Replaces header with 603 error.
I have setup where Opensips generates new INVITE with Replaces upon receiving REFER.
Call goes as follows:
A —> B —> C
A ← REFER – B
A —> C
A initiates call to B. B answers and calls to C.
Once C(asterisk) answers it plays musiconhold.
B sends REFER to A with Refer-To header including Replaces parameter with dialog information(callid, from-tag, to-tag) .
A sends INVITE to C with Replaces header including dialog information of B and C call.
B hangs up the call.

The problem is that in the exact same scheme Asterisk sometimes accept INVITE with Replaces and switch channels with A and C, so A hears musiconhold, but sometimes it rejects INVITE with error 603 Declined.
I compared INVITEs of good call and bad call - they are the same apart from dialog information - IPs, headers, everything. On asterisk debug i don’t see any reason for decline except of message that it failed, no reason, no any details info.

I can’t attcah files, so i put debug info below with INVITEs with Replaces and core debug output from asterisk, to failed call i also attached 200OK with dialog information so it can be seen that dialog information in Replaces is passed accordingly with real callid, from/to-tags of first call.

I’m using Asterisk 18.7 with PJSIP
Here is core settings output:

PBX Core settings
-----------------
  Version:                     18.7.1
  Build Options:               BUILD_NATIVE, OPTIONAL_API
  Maximum calls:               Not set
  Maximum open file handles:   65000
  Root console verbosity:      0
  Current console verbosity:   0
  Debug level:                 9
  Trace level:                 0
  Maximum load average:        0.000000
  Minimum free memory:         0 MB
  Startup time:                12:02:09
  Last reload time:            12:04:00
  System:                      Linux/3.10.0-1160.31.1.el7.x86_64 built by root on x86_64 2022-10-21 08:31:07 UTC
  System name:                 
  Entity ID:                   ID
  PBX UUID:                    7fd2772f-6746-4eed-9c5b-bf010d5f9835
  Default language:            en
  Language prefix:             Enabled
  User name and group:         root/root
  Executable includes:         Enabled
  Transcode via SLIN:          Enabled
  Transmit silence during rec: Disabled
  Generic PLC:                 Disabled
  Generic PLC on equal codecs: Disabled
  Hide Msg Chan AMI events:    Disabled
  Min DTMF duration::          80
  Cache media frames:          Enabled
  RTP use dynamic payloads:    1
  RTP dynamic payload types:   35-63,96-127

* Subsystems
  -------------
  Manager (AMI):               Enabled
  Web Manager (AMI/HTTP):      Disabled
  Call data records:           Enabled
  Realtime Architecture (ARA): Disabled

Any help would be much appreciated!

2

Failed call:

########## OK of INITIAL call
SIP/2.0 200 OK
Via: SIP/2.0/UDP 777777777777;received=PROXY_IP;branch=z9hG4bK2031.4ed854ce9b93bc2313a2e03e74c98b4e.0
Via: SIP/2.0/UDP PROXY_IP;branch=z9hG4bKsr-mCf6F.h4TcQ1kauSTJu4TKTtFKTPFKE.s3oVB3oCNJmV0KuA1XSQL-fHsHotlpDKiqPxspOI0-oFTKu.TMww0KhwTKkO0qEV0JL8TJ0K0.kesJUflHkOTJnDT8XdLMwV
Via: SIP/2.0/UDP PROXY_IP;branch=z9hG4bKsr-mCf6F.h4TcQ1kauSTJu4TKTtFKTPFKE.sHotlpDKiqPxspOI0-oFE3hrBm080nl4iqkmlPXdiHaPmPkG2JkmMPk6knrlFfkf2H6VEpDUkYf1mn1D0fXVMy1h1IatBmPdm-DbppdUBIfRJChwT-bsppbXi1Oa6Hd40CO
qUOitPj2.mrTauVM-oF0pPO2u**
Record-Route: <sip:PROXY_IP;lr;did=bc2.6ed1;nat=yes>
Record-Route: <sip:PROXY_IP;line=sr-EHfVsKXVFKh.Tew.0Mw3T.r7EKPRBKrnip6Ql8TtF8TP0.h*>
Call-ID: Y7AJCKy6bRkG8tA0@m1-ira-sipp-01pre
From: <sip:4929@SOURCE_IP>;tag=VF102AdGxQvhBJlmQbLah2t8cGNRNtKZ
To: <sip:777777777777@PROXY_IP2>;tag=613d3efd-4569-433b-9742-c6e6ee584f80
CSeq: 1 INVITE
Server: ASTERISK_DOMAIN
Contact: <sip:ASTERISK_IP:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   219

v=0
o=- 0 2 IN IP4 ASTERISK_IP
s=Asterisk
c=IN IP4 ASTERISK_IP
t=0 0
m=audio 63664 RTP/AVP 8 127
a=rtpmap:8 PCMA/8000
a=rtpmap:127 telephone-event/8000
a=fmtp:127 0-16
a=ptime:20
a=maxptime:150
a=sendrecv



######## FAILED INVITE with Replaces
INVITE sip:777777777777@PROXY_IP SIP/2.0
Record-Route: <sip:PROXY_IP;lr=on;did=35e.8651;nat=yes>
Record-Route: <sip:PROXY_IP;line=sr-EHfVsKXVFKh.Tew.0Mw3T.r7EKPRBKrnip6QT.1fFKT.0u**>
Via: SIP/2.0/UDP PROXY_IP;branch=z9hG4bK88ed.1b1c1cc6d6eceffca9341c67dae8510b.0
Via: SIP/2.0/UDP PROXY_IP;branch=z9hG4bKsr-mCf6F.h4TcQ1kauSTJu4TKTtFKTPFKE.s3oVB3oCNJmV0KuA1XSQL-fHsHotlpDKiqPxspOI0-oFsqOfLcDe0pTCl.SdLKLK0q18TKuDsJ08l8TH0p6dsJEdLqlCltwV
Via: SIP/2.0/UDP PROXY_IP;branch=z9hG4bKsr-mCf6F.h4TcQ1kauSTJu4TKTtFKTPFKE.sHotlpDKiqPxspOI0-oFE3hrBm080nl4iqkmlPXdiHaPmPkG2JkmMPkCknrmmXLFBfU.MHPpTXrP6m1D11oa5JLkTXbPMakdE8P0E1U4i1f76pdDBCQcsqUZJffZk-flkm0
K23EtCdBnLFJX7VM.L3E3U7FnLF2Mj*
To: sip:777777777777@PROXY_IP2
From: <sip:4929@SOURCE_IP2>;tag=a1fc4bc5844507050c2185ba21eec69f-39eb
CSeq: 3 INVITE
Call-ID: B2B.16169.1177273.1666348549
Max-Forwards: 66
Content-Length: 237
User-Agent: OpenSIPS (3.2.8 (x86_64/linux))
Content-Type: application/sdp
Supported: 100rel, timer, replaces, norefersub
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Session-Expires: 600
Min-SE: 90
Contact: <sip:PROXY_IP;line=sr-EHfVsKXVFKh.Tew.0Mw3T.r7ipDfNY0tFm1hLfL.MPOpknrjFfkf2twVJY2XTXbtJChrLnQaFn0n1-032a64iqkmF8CCECjd5KUG2mOmMY2n>
Replaces: Y7AJCKy6bRkG8tA0@m1-ira-sipp-01pre;from-tag=VF102AdGxQvhBJlmQbLah2t8cGNRNtKZ;to-tag=613d3efd-4569-433b-9742-c6e6ee584f80


v=0
o=- 1480668715 1480668715 IN IP4 SOURCE_IP2
s=Asterisk
c=IN IP4 SOURCE_IP2
t=0 0
m=audio 63952 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv


#######Asterisk debug output on INVITE with replaces
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4738 session_inv_on_tsx_state_changed:  PJSIP/proxy-trunk-00000044 TSX State: Completed  Inv State: DISCONNCTD
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk(PJSIP/proxy-trunk-00000044)'
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4379 __print_debug_details: The inv session does NOT have an invite_tsx
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4382 __print_debug_details: The UAS BYE transaction involved in this state change is 0x7fae18047b38
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4386 __print_debug_details: The current transaction state is Completed
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4388 __print_debug_details: The transaction state change event is RX_MSG
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is DISCONNCTD
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4925 session_inv_on_tsx_state_changed:  Nothing delayed
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4170 session_on_tsx_state:  PJSIP/proxy-trunk-00000044 TSX State: Completed  Inv State: DISCONNCTD
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4175 session_on_tsx_state:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4178 session_on_tsx_state:  
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2975 chan_pjsip_session_end:  PJSIP/proxy-trunk-00000044
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2992 chan_pjsip_session_end:  
[2022-10-21 13:35:49] DEBUG[897][C-00000023]: channel.c:2747 __ast_answer: Hangup of channel PJSIP/proxy-trunk-00000044 detected in answer routine
[2022-10-21 13:35:49] DEBUG[897][C-00000023]: pbx.c:4441 __ast_pbx_run: Spawn extension (from-internal,777777777777,2) exited non-zero on 'PJSIP/proxy-trunk-00000044'
[2022-10-21 13:35:49] DEBUG[897][C-00000023]: channel.c:2461 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/proxy-trunk-00000044'
[2022-10-21 13:35:49] DEBUG[897][C-00000023]: channel.c:2552 ast_hangup: Channel 0x7fae30021230 'PJSIP/proxy-trunk-00000044' hanging up.  Refs: 2
[2022-10-21 13:35:49] DEBUG[897][C-00000023]: chan_pjsip.c:2522 chan_pjsip_hangup:  PJSIP/proxy-trunk-00000044
[2022-10-21 13:35:49] DEBUG[897][C-00000023]: chan_pjsip.c:2442 hangup_cause2sip: AST hangup cause 16 (no match found in PJSIP)
[2022-10-21 13:35:49] DEBUG[897][C-00000023]: chan_pjsip.c:2540 chan_pjsip_hangup:  Cause: 0
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2489 hangup:  PJSIP/proxy-trunk-00000044
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:3455 ast_sip_session_terminate:  PJSIP/proxy-trunk-00000044 Response 0
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae30019660) DTLS srtp - stopped timeout timer'
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae30019660) DTLS srtp - stopped timeout timer'
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2275 ast_rtp_dtls_stop: (0x7fae30019660) DTLS stop
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae30019660) DTLS srtp - stopped timeout timer'
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae30019660) DTLS srtp - stopped timeout timer'
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:3982 rtp_deallocate_transport: (0x7fae30019660) ICE RTP transport deallocating
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:455 instance_destructor: Destroyed RTP instance '0x7fae30019660'
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:3527 ast_sip_session_terminate:  
[2022-10-21 13:35:49] DEBUG[470]: channel.c:2198 ast_channel_destructor: Channel 0x7fae30021230 'PJSIP/proxy-trunk-00000044' destroying
[2022-10-21 13:35:49] DEBUG[26362]: cdr.c:1470 cdr_object_finalize: Finalized CDR for PJSIP/proxy-trunk-00000044 - start 1666348549.329031 answer 1666348549.331063 end 1666348549.500473 dur 0.171 bill 0.169 dispo ANSWERED
[2022-10-21 13:35:49] DEBUG[470]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348549.417, detail: 
[2022-10-21 13:35:49] DEBUG[470]: stasis.c:450 topic_dtor: Topic 'channel:1666348549.417': 0x7fae30023850 destroyed
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:682 ast_channel_nativeformats_set:  <initializing>: MultistreamFormats: (nothing)
[2022-10-21 13:35:49] DEBUG[26353]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for PJSIP - proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:692 ast_channel_nativeformats_set:  Channel is being initialized or destroyed
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2513 hangup:  
[2022-10-21 13:35:49] DEBUG[26353]: devicestate.c:466 do_state_change: Changing state for PJSIP/proxy-trunk - state 1 (Not in use)
[2022-10-21 13:35:49] DEBUG[26406]: app_queue.c:2589 device_state_cb: Device 'PJSIP/proxy-trunk' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:1666348549.420, detail: 
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:1666348549.420': 0x7fae38007c00 created
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348549.420, detail: 
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:450 topic_dtor: Topic 'channel:1666348549.420': 0x7fae38007c00 destroyed
[2022-10-21 13:35:49] DEBUG[26363]: cel_radius.c:193 radius_log: Unable to create RADIUS record. CEL not recorded!
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:1666348549.421, detail: 
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:1666348549.421': 0x7fae38008810 created
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348549.421, detail: 
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:450 topic_dtor: Topic 'channel:1666348549.421': 0x7fae38008810 destroyed
[2022-10-21 13:35:49] DEBUG[26363]: cel_radius.c:193 radius_log: Unable to create RADIUS record. CEL not recorded!
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:1666348549.422, detail: 
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:1666348549.422': 0x7fae38007e60 created
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348549.422, detail: 
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:450 topic_dtor: Topic 'channel:1666348549.422': 0x7fae38007e60 destroyed
[2022-10-21 13:35:49] DEBUG[26363]: cel_radius.c:193 radius_log: Unable to create RADIUS record. CEL not recorded!
[2022-10-21 13:35:49] DEBUG[26371]: res_pjsip/pjsip_distributor.c:394 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=3 (rdata0x7fae78001bb8)
[2022-10-21 13:35:49] DEBUG[26371]: res_pjsip/pjsip_distributor.c:472 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000036 to use for Request msg INVITE/cseq=3 (rdata0x7fae78001bb8)
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'PROXY_IP' into...
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'PROXY_IP' and port ''.
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_endpoint_identifier_ip.c:255 ip_identify_match_check: Source address PROXY_IP:5060 matches identify 'proxy-trunk'
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_endpoint_identifier_ip.c:288 common_identify: Identify 'proxy-trunk' SIP message matched to endpoint proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4225 session_on_rx_request:  (null session) Request: INVITE 
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4059 handle_new_invite_request:  Request: 
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip/pjsip_distributor.c:472 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000036 to use for Request msg INVITE/cseq=3 (rdata0x7fae78022f48)
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2954 chan_pjsip_session_begin:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2958 chan_pjsip_session_begin:  Direct media no glare mitigation
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:3918 new_invite:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4002 new_invite:  proxy-trunk: Call (UDP:PROXY_IP:5060) to extension '777777777777' sending 100 Trying
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4506 handle_outgoing_response:  proxy-trunk: Method is INVITE, Response is 100 Trying
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4522 handle_outgoing_response:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target 'PROXY_IP'
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target 'PROXY_IP' is 'UDP transport'
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target 'PROXY_IP' is an IP address, skipping resolution
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4620 session_inv_on_state_changed:  proxy-trunk Event: TSX_STATE  Inv State: INCOMING
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk()'
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4376 __print_debug_details: The inv session still has an invite_tsx (0x7fae180398d8)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4391 __print_debug_details: There is no transaction involved in this state change
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is INCOMING
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4646 session_inv_on_state_changed: proxy-trunk: Source of transaction state change is TX_MSG
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4693 session_inv_on_state_changed:  
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4738 session_inv_on_tsx_state_changed:  proxy-trunk TSX State: Proceeding  Inv State: INCOMING
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk()'
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4376 __print_debug_details: The inv session still has an invite_tsx (0x7fae180398d8)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4382 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fae180398d8
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4386 __print_debug_details: The current transaction state is Proceeding
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4388 __print_debug_details: The transaction state change event is TX_MSG
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is INCOMING
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4925 session_inv_on_tsx_state_changed:  Nothing delayed
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4170 session_on_tsx_state:  proxy-trunk TSX State: Proceeding  Inv State: INCOMING
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4175 session_on_tsx_state:  Topology: Pending: (null topology)  Active: (null topology)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4178 session_on_tsx_state:  
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:769 handle_incoming_sdp:  proxy-trunk: Media count: 1
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:795 handle_incoming_sdp:  proxy-trunk: Processing stream 0
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:833 handle_incoming_sdp:  proxy-trunk: Using audio-0 for new stream name
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:877 handle_incoming_sdp:  proxy-trunk: Using new stream 0:audio-0:audio:sendrecv (nothing)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:495 ast_sip_session_media_state_add:  proxy-trunk Adding position 0
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:541 ast_sip_session_media_state_add:  Creating new media session
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:584 ast_sip_session_media_state_add:  Setting media session as default for audio
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:589 ast_sip_session_media_state_add:  Done
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:931 handle_incoming_sdp:  proxy-trunk: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_sdp_rtp.c:1497 negotiate_incoming_sdp_stream:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'SOURCE_IP2' into...
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'SOURCE_IP2' and port ''.
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '0.0.0.0' into...
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port ''.
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_sdp_rtp.c:261 create_rtp: Transport udp-transport bound to 0.0.0.0: Using it for RTP media.
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:526 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fae300235b0'
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:3872 rtp_allocate_transport: (0x7fae300235b0) RTP allocated port 63450
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:3903 rtp_allocate_transport: (0x7fae300235b0) ICE creating session 0.0.0.0:63450 (63450)
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:3784 ice_create: (0x7fae300235b0) ICE create
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:3561 rtp_add_candidates_to_ice: (0x7fae300235b0) ICE add system candidates
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'ASTERISK_IP' into...
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'ASTERISK_IP' and port ''.
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:1330 ast_rtp_ice_add_cand: (0x7fae300235b0) ICE add candidate: ASTERISK_IP:63450, 2130706431
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:543 ast_rtp_instance_new: RTP instance '0x7fae300235b0' is setup and ready to go
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:918 ast_rtp_ice_stop: (0x7fae300235b0) ICE stopped
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'ASTERISK_DOMAIN' into...
[2022-10-21 13:35:49] DEBUG[470]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'ASTERISK_DOMAIN' and port ''.
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:8433 ast_rtp_prop_set: (0x7fae300235b0) RTCP setup on RTP instance
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_sdp_rtp.c:446 set_incoming_call_offer_cap:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_sdp_rtp.c:328 get_codecs:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:1319 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7fae11ae2190
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_sdp_rtp.c:404 get_codecs:  
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session/pjsip_session_caps.c:161 ast_sip_session_create_joint_call_cap: 'proxy-trunk' Caps for incoming audio call with pref 'local' - remote: (alaw) local: (alaw) joint: (alaw)
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:1283 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 8 (0x7fae30008968) from 0x7fae11ae2190 to 0x7fae11ae2190
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:1283 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 101 (0x7fae300111f8) from 0x7fae11ae2190 to 0x7fae11ae2190
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:1120 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 8 (0x7fae30008968) from 0x7fae11ae2190 to 0x7fae30023788
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:1120 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 101 (0x7fae300111f8) from 0x7fae11ae2190 to 0x7fae30023788
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:1205 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 8 (0x7fae30008968) from 0x7fae11ae2190 to 0x7fae30023788
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:1205 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 101 (0x7fae300111f8) from 0x7fae11ae2190 to 0x7fae30023788
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_sdp_rtp.c:482 set_incoming_call_offer_cap:  
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_sdp_rtp.c:1587 negotiate_incoming_sdp_stream:  
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:950 handle_incoming_sdp:  proxy-trunk: Media stream 0:audio-0:audio:sendrecv (alaw) handled by audio
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:956 handle_incoming_sdp:  proxy-trunk: Done with stream 0:audio-0:audio:sendrecv (alaw)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:961 handle_incoming_sdp:  proxy-trunk: Handled? yes
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5089 create_local_sdp:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5126 create_local_sdp:  proxy-trunk: Processing streams
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5133 create_local_sdp:  proxy-trunk: Processing stream 0:audio-0:audio:sendrecv (alaw)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:495 ast_sip_session_media_state_add:  proxy-trunk Adding position 0
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:503 ast_sip_session_media_state_add:  Using existing media_session
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4966 add_sdp_streams:  proxy-trunk Stream: 0:audio-0:audio:sendrecv (alaw)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_sdp_rtp.c:1743 create_outgoing_sdp_stream:  proxy-trunk Type: audio 0:audio-0:audio:sendrecv (alaw)
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:8332 ast_rtp_prop_set: (0x7fae300235b0) RTCP ignoring duplicate property
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_sdp_rtp.c:2027 create_outgoing_sdp_stream:  RC: 1
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4974 add_sdp_streams:  Had handler
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5166 create_local_sdp:  proxy-trunk: Stream 0:audio-0:audio:sendrecv (alaw) added
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5178 create_local_sdp:  proxy-trunk: Done with 0:audio-0:audio:sendrecv (alaw)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5183 create_local_sdp:  proxy-trunk: Adding bundle groups (if available)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5189 create_local_sdp:  proxy-trunk: Copying connection details
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5192 create_local_sdp:  proxy-trunk: Processing media 0
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5210 create_local_sdp:  proxy-trunk: Media 0 reset
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:5233 create_local_sdp:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4402 handle_incoming_request:  proxy-trunk: Method is INVITE
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:3013 chan_pjsip_incoming_request:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:555 chan_pjsip_new:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:682 ast_channel_nativeformats_set:  <initializing>: Formats: (none)
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:692 ast_channel_nativeformats_set:  Channel is being initialized or destroyed
[2022-10-21 13:35:49] DEBUG[470]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:1666348549.423, detail: 
[2022-10-21 13:35:49] DEBUG[470]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:1666348549.423': 0x7fae300209e0 created
[2022-10-21 13:35:49] DEBUG[470]: channel.c:951 __ast_channel_alloc_ap: Channel 0x7fae3001bf80 'PJSIP/proxy-trunk-00000045' allocated
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:532 compatible_formats_exist:  Topology:  <0:audio-0:audio:sendrecv (alaw)> Formats: (alaw)
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:543 compatible_formats_exist:  Compatible? yes
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:682 ast_channel_nativeformats_set:  PJSIP/proxy-trunk-00000045: MultistreamFormats: (alaw)
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:702 ast_channel_nativeformats_set:  Set native formats but not topology
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:1596 ast_channel_set_stream_topology:  PJSIP/proxy-trunk-00000045:  <0:audio-0:audio:sendrecv (alaw)>
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:1616 ast_channel_set_stream_topology:  Used provided topology
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:675 chan_pjsip_new:  
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:3063 chan_pjsip_incoming_request:  PJSIP/proxy-trunk-00000045
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:1666348549.424, detail: 
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:1666348549.424': 0x7fae38006930 created
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_refer.c:1071 refer_incoming_invite_request: INVITE with Replaces failed on channel 'PJSIP/proxy-trunk-00000045', sending response of '603'
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348549.424, detail: 
[2022-10-21 13:35:49] DEBUG[470]: channel.c:2552 ast_hangup: Channel 0x7fae3001bf80 'PJSIP/proxy-trunk-00000045' hanging up.  Refs: 2
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:450 topic_dtor: Topic 'channel:1666348549.424': 0x7fae38006930 destroyed
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2522 chan_pjsip_hangup:  PJSIP/proxy-trunk-00000045
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2442 hangup_cause2sip: AST hangup cause 0 (no match found in PJSIP)
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2540 chan_pjsip_hangup:  Cause: 0
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4506 handle_outgoing_response:  PJSIP/proxy-trunk-00000045: Method is INVITE, Response is 603 Decline
[2022-10-21 13:35:49] DEBUG[26363]: cel_radius.c:193 radius_log: Unable to create RADIUS record. CEL not recorded!
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4522 handle_outgoing_response:  PJSIP/proxy-trunk-00000045
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4620 session_inv_on_state_changed:  PJSIP/proxy-trunk-00000045 Event: TSX_STATE  Inv State: DISCONNCTD
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk(PJSIP/proxy-trunk-00000045)'
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4376 __print_debug_details: The inv session still has an invite_tsx (0x7fae180398d8)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4391 __print_debug_details: There is no transaction involved in this state change
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is DISCONNCTD
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4646 session_inv_on_state_changed: PJSIP/proxy-trunk-00000045: Source of transaction state change is TX_MSG
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4693 session_inv_on_state_changed:  
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4738 session_inv_on_tsx_state_changed:  PJSIP/proxy-trunk-00000045 TSX State: Completed  Inv State: DISCONNCTD
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk(PJSIP/proxy-trunk-00000045)'
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4376 __print_debug_details: The inv session still has an invite_tsx (0x7fae180398d8)
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4382 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fae180398d8
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4386 __print_debug_details: The current transaction state is Completed
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4388 __print_debug_details: The transaction state change event is TX_MSG
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is DISCONNCTD
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4759 session_inv_on_tsx_state_changed:  Disconnected
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4170 session_on_tsx_state:  (null session) TSX State: Completed  Inv State: DISCONNCTD
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4178 session_on_tsx_state:  
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4412 handle_incoming_request:  PJSIP/proxy-trunk-00000045
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4047 new_invite:  PJSIP/proxy-trunk-00000045
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4125 handle_new_invite_request:  Request:  Session: PJSIP/proxy-trunk-00000045
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:4245 session_on_rx_request:  (null session) Handled request INVITE  ? yes
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2489 hangup:  PJSIP/proxy-trunk-00000045
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:3455 ast_sip_session_terminate:  PJSIP/proxy-trunk-00000045 Response 0
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:3459 ast_sip_session_terminate:  Deferred
[2022-10-21 13:35:49] DEBUG[470]: channel.c:2198 ast_channel_destructor: Channel 0x7fae3001bf80 'PJSIP/proxy-trunk-00000045' destroying
[2022-10-21 13:35:49] DEBUG[470]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348549.423, detail: 
[2022-10-21 13:35:49] DEBUG[470]: stasis.c:450 topic_dtor: Topic 'channel:1666348549.423': 0x7fae300209e0 destroyed
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:682 ast_channel_nativeformats_set:  <initializing>: MultistreamFormats: (nothing)
[2022-10-21 13:35:49] DEBUG[470]: channel_internal_api.c:692 ast_channel_nativeformats_set:  Channel is being initialized or destroyed
[2022-10-21 13:35:49] DEBUG[26362]: cdr.c:1470 cdr_object_finalize: Finalized CDR for PJSIP/proxy-trunk-00000045 - start 1666348549.507043 answer 0.000000 end 1666348549.507418 dur 0.000 bill 1666348549.507 dispo FAILED
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2513 hangup:  
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2975 chan_pjsip_session_end:  proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: chan_pjsip.c:2978 chan_pjsip_session_end:  No channel
[2022-10-21 13:35:49] DEBUG[26362]: cdr.c:3523 post_cdr: Skipping CDR for PJSIP/proxy-trunk-00000045 since we weren't answered
[2022-10-21 13:35:49] DEBUG[470]: res_pjsip_session.c:2911 session_destructor: proxy-trunk: Destroying SIP session
[2022-10-21 13:35:49] DEBUG[26353]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for PJSIP - proxy-trunk
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae300235b0) DTLS srtp - stopped timeout timer'
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae300235b0) DTLS srtp - stopped timeout timer'
[2022-10-21 13:35:49] DEBUG[26353]: devicestate.c:466 do_state_change: Changing state for PJSIP/proxy-trunk - state 1 (Not in use)
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2275 ast_rtp_dtls_stop: (0x7fae300235b0) DTLS stop
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae300235b0) DTLS srtp - stopped timeout timer'
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae300235b0) DTLS srtp - stopped timeout timer'
[2022-10-21 13:35:49] DEBUG[470]: res_rtp_asterisk.c:3982 rtp_deallocate_transport: (0x7fae300235b0) ICE RTP transport deallocating
[2022-10-21 13:35:49] DEBUG[470]: rtp_engine.c:455 instance_destructor: Destroyed RTP instance '0x7fae300235b0'
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:1666348549.425, detail: 
[2022-10-21 13:35:49] DEBUG[26363]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:1666348549.425': 0x7fae38007be0 created
3

Successful:

######## SUCCESSFUL INVITE with Replaces
INVITE sip:777777777777@PROXY_IP SIP/2.0
Record-Route: <sip:PROXY_IP;lr=on;did=50a.456;nat=yes>
Record-Route: <sip:PROXY_IP;line=sr-EHfVsKXVFKh.Tew.0Mw3T.r7EKPRBKrnip6Q0JUOFKnPT.h*>
Via: SIP/2.0/UDP PROXY_IP;branch=z9hG4bKa3ab.c07df225e7b692542c60328857f13fb4.0
Via: SIP/2.0/UDP PROXY_IP;branch=z9hG4bKsr-mCf6F.h4TcQ1kauSTJu4TKTtFKTPFKE.s3oVB3oCNJmV0KuA1XSQL-fHsHotlpDKiqPxspOI0-oFlJ0OlewVlH1f0KhPlHo8T8mVLKS.lJlHT-hV0pX.TJonlJTDTewV
Via: SIP/2.0/UDP PROXY_IP;branch=z9hG4bKsr-mCf6F.h4TcQ1kauSTJu4TKTtFKTPFKE.sHotlpDKiqPxspOI0-oFE3hrBm080nl4iqkmlPXdiHaPmPkG2JkmMPkCknrmmXLFBfU.MHPpTXrP6m1D11oa5JLkTXbPMakdE8P0E1U4i1f76pdDBCQcsqUZJffZk-flkm0
yoN1XOOLmLFBXO7FnQ8JIUrMXLF2Mj*
To: sip:777777777777@4929
From: <sip:4929@SOURCE_IP2>;tag=a1fc4bc5844507050c2185ba21eec69f-9e40
CSeq: 3 INVITE
Call-ID: B2B.16169.7355475.1666348436
Max-Forwards: 66
Content-Length: 235
User-Agent: OpenSIPS (3.2.8 (x86_64/linux))
Content-Type: application/sdp
Supported: 100rel, timer, replaces, norefersub
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Session-Expires: 600
Min-SE: 90
Contact: <sip:PROXY_IP;line=sr-EHfVsKXVFKh.Tew.0Mw3T.r7ipDfNY0tFm1hLfL.MPOpknrjFfkf2twVJY2XTXbtJChrLnQaFn0n1-032a64iqkmF8CCECjd5KUG2mOmMY2n>
Replaces: L4B9Qp0O3JEpsFZW@m1-ira-sipp-01pre;from-tag=ECHIHlnKRaoSHXjdB3m4YbXmc6U87duq;to-tag=ce6f2974-0939-456c-b838-b4f3f17168bf


v=0
o=- 293012017 293012017 IN IP4 SOURCE_IP2
s=Asterisk
c=IN IP4 SOURCE_IP2
t=0 0
m=audio 58976 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv


#######Asterisk debug output on INVITE with replaces
[2022-10-21 13:33:56] DEBUG[470]: channel_internal_api.c:702 ast_channel_nativeformats_set:  Set native formats but not topology
[2022-10-21 13:33:56] DEBUG[470]: channel.c:5752 set_format: Channel PJSIP/proxy-trunk-00000043 setting read format path: alaw -> alaw
[2022-10-21 13:33:56] DEBUG[470]: channel.c:5752 set_format: Channel PJSIP/proxy-trunk-00000043 setting write format path: alaw -> alaw
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_sdp_rtp.c:611 set_caps:  
[2022-10-21 13:33:56] DEBUG[470]: res_rtp_asterisk.c:9112 ast_rtp_activate: (0x7fae30049450) DTLS - ast_rtp_activate rtp=0x7fae3004a400 - setup and perform DTLS'
[2022-10-21 13:33:56] DEBUG[470]: res_rtp_asterisk.c:2549 dtls_perform_handshake: (0x7fae3004a400) DTLS perform handshake - ssl = (nil), setup = 0
[2022-10-21 13:33:56] DEBUG[470]: res_rtp_asterisk.c:2549 dtls_perform_handshake: (0x7fae3004a400) DTLS perform handshake - ssl = (nil), setup = 0
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_sdp_rtp.c:2234 apply_negotiated_sdp_stream:  Handled
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:1012 handle_negotiated_sdp_session_media: PJSIP/proxy-trunk-00000043: Applied negotiated SDP media stream 'audio' using audio SDP handler
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:1015 handle_negotiated_sdp_session_media:  PJSIP/proxy-trunk-00000043: Applied negotiated SDP media stream 'audio' using audio SDP handler
[2022-10-21 13:33:56] DEBUG[470]: channel_internal_api.c:1596 ast_channel_set_stream_topology:  PJSIP/proxy-trunk-00000043:  <0:audio-0:audio:sendrecv (alaw)>
[2022-10-21 13:33:56] DEBUG[470]: channel_internal_api.c:1616 ast_channel_set_stream_topology:  Used provided topology
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:1223 handle_negotiated_sdp:  
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:5402 session_inv_on_media_update:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4506 handle_outgoing_response:  PJSIP/proxy-trunk-00000043: Method is INVITE, Response is 200 OK
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4522 handle_outgoing_response:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip/pjsip_message_filter.c:297 filter_on_tx_message: Re-wrote Contact URI host/port to ASTERISK_IP:5060 (this may be re-written again later)
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4620 session_inv_on_state_changed:  PJSIP/proxy-trunk-00000043 Event: TSX_STATE  Inv State: CONNECTING
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk(PJSIP/proxy-trunk-00000043)'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4376 __print_debug_details: The inv session still has an invite_tsx (0x7fae1805b5f8)
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4391 __print_debug_details: There is no transaction involved in this state change
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is CONNECTING
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4646 session_inv_on_state_changed: PJSIP/proxy-trunk-00000043: Source of transaction state change is TX_MSG
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4693 session_inv_on_state_changed:  
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4738 session_inv_on_tsx_state_changed:  PJSIP/proxy-trunk-00000043 TSX State: Completed  Inv State: CONNECTING
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk(PJSIP/proxy-trunk-00000043)'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4376 __print_debug_details: The inv session still has an invite_tsx (0x7fae1805b5f8)
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4382 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fae1805b5f8
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4386 __print_debug_details: The current transaction state is Completed
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4388 __print_debug_details: The transaction state change event is TX_MSG
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is CONNECTING
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4925 session_inv_on_tsx_state_changed:  Nothing delayed
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4170 session_on_tsx_state:  PJSIP/proxy-trunk-00000043 TSX State: Completed  Inv State: CONNECTING
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4175 session_on_tsx_state:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4178 session_on_tsx_state:  
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:723 answer:  
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:762 chan_pjsip_answer:  
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1633 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000043: Indicated Stop generators
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1843 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_refer.c:1020 refer_incoming_invite_request: INVITE with Replaces being attempted.  'PJSIP/proxy-trunk-00000043' --> 'PJSIP/proxy-trunk-00000042'
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1633 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000042: Indicated Masquerade notify
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1843 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000042
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1633 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000043: Indicated Masquerade notify
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1843 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1633 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000042: Indicated Stop generators
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1843 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000042
[2022-10-21 13:33:56] DEBUG[470]: channel.c:6950 channel_do_masquerade: Actually Masquerading PJSIP/proxy-trunk-00000043(6) into the structure of PJSIP/proxy-trunk-00000042(6)
[2022-10-21 13:33:56] DEBUG[470]: channel_internal_api.c:682 ast_channel_nativeformats_set:  PJSIP/proxy-trunk-00000043: MultistreamFormats: (alaw)
[2022-10-21 13:33:56] DEBUG[470]: channel_internal_api.c:702 ast_channel_nativeformats_set:  Set native formats but not topology
[2022-10-21 13:33:56] DEBUG[470]: channel.c:5752 set_format: Channel PJSIP/proxy-trunk-00000043 setting write format path: alaw -> alaw
[2022-10-21 13:33:56] DEBUG[470]: channel.c:5752 set_format: Channel PJSIP/proxy-trunk-00000043 setting read format path: alaw -> alaw
[2022-10-21 13:33:56] DEBUG[470]: channel.c:7218 channel_do_masquerade: Putting channel PJSIP/proxy-trunk-00000043 in alaw/alaw formats
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1633 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000043: Indicated Masquerade notify
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1843 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1633 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000042: Indicated Masquerade notify
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1843 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000042
[2022-10-21 13:33:56] DEBUG[470]: channel.c:7321 channel_do_masquerade: Done Masquerading PJSIP/proxy-trunk-00000043 (6)
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1633 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000043: Indicated Media SSRC change
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:1843 chan_pjsip_indicate:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: channel.c:2552 ast_hangup: Channel 0x7fae30051720 'PJSIP/proxy-trunk-00000042' hanging up.  Refs: 2
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:2522 chan_pjsip_hangup:  PJSIP/proxy-trunk-00000042
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:2442 hangup_cause2sip: AST hangup cause 0 (no match found in PJSIP)
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:2540 chan_pjsip_hangup:  Cause: 0
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_refer.c:1056 refer_incoming_invite_request: INVITE with Replaces successfully completed.
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4412 handle_incoming_request:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4047 new_invite:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4125 handle_new_invite_request:  Request:  Session: PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4245 session_on_rx_request:  (null session) Handled request INVITE  ? yes
[2022-10-21 13:33:56] DEBUG[740]: chan_pjsip.c:2489 hangup:  PJSIP/proxy-trunk-00000042
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:3455 ast_sip_session_terminate:  PJSIP/proxy-trunk-00000042 Response 0
[2022-10-21 13:33:56] DEBUG[740]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae300081d0) DTLS srtp - stopped timeout timer'
[2022-10-21 13:33:56] DEBUG[740]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae300081d0) DTLS srtp - stopped timeout timer'
[2022-10-21 13:33:56] DEBUG[740]: res_rtp_asterisk.c:2275 ast_rtp_dtls_stop: (0x7fae300081d0) DTLS stop
[2022-10-21 13:33:56] DEBUG[740]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae300081d0) DTLS srtp - stopped timeout timer'
[2022-10-21 13:33:56] DEBUG[740]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7fae300081d0) DTLS srtp - stopped timeout timer'
[2022-10-21 13:33:56] DEBUG[740]: res_rtp_asterisk.c:3982 rtp_deallocate_transport: (0x7fae300081d0) ICE RTP transport deallocating
[2022-10-21 13:33:56] DEBUG[740]: rtp_engine.c:455 instance_destructor: Destroyed RTP instance '0x7fae300081d0'
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4486 handle_outgoing_request:  PJSIP/proxy-trunk-00000042: Method is BYE
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4495 handle_outgoing_request:  PJSIP/proxy-trunk-00000042
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target 'PROXY_IP'
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target 'PROXY_IP' is 'UDP transport'
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target 'PROXY_IP' is an IP address, skipping resolution
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4738 session_inv_on_tsx_state_changed:  PJSIP/proxy-trunk-00000042 TSX State: Calling  Inv State: CONFIRMED
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk(PJSIP/proxy-trunk-00000042)'
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4379 __print_debug_details: The inv session does NOT have an invite_tsx
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4382 __print_debug_details: The UAC BYE transaction involved in this state change is 0x7fae1805a508
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4386 __print_debug_details: The current transaction state is Calling
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4388 __print_debug_details: The transaction state change event is TX_MSG
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is CONFIRMED
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4925 session_inv_on_tsx_state_changed:  Nothing delayed
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4170 session_on_tsx_state:  PJSIP/proxy-trunk-00000042 TSX State: Calling  Inv State: CONFIRMED
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4175 session_on_tsx_state:  Topology: Pending: (null topology)  Active: (null topology)
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:4178 session_on_tsx_state:  
[2022-10-21 13:33:56] DEBUG[740]: res_pjsip_session.c:3527 ast_sip_session_terminate:  
[2022-10-21 13:33:56] DEBUG[740]: channel.c:2198 ast_channel_destructor: Channel 0x7fae30051720 'PJSIP/proxy-trunk-00000042' destroying
[2022-10-21 13:33:56] DEBUG[740]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348436.404, detail: 
[2022-10-21 13:33:56] DEBUG[740]: stasis.c:450 topic_dtor: Topic 'channel:1666348436.404': 0x7fae30007240 destroyed
[2022-10-21 13:33:56] DEBUG[740]: channel_internal_api.c:682 ast_channel_nativeformats_set:  <initializing>: MultistreamFormats: (nothing)
[2022-10-21 13:33:56] DEBUG[740]: channel_internal_api.c:692 ast_channel_nativeformats_set:  Channel is being initialized or destroyed
[2022-10-21 13:33:56] DEBUG[740]: chan_pjsip.c:2513 hangup:  
[2022-10-21 13:33:56] DEBUG[26353]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for PJSIP - proxy-trunk
[2022-10-21 13:33:56] DEBUG[26353]: devicestate.c:466 do_state_change: Changing state for PJSIP/proxy-trunk - state 2 (In use)
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:1666348436.410, detail: 
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:1666348436.410': 0x7fae38005690 created
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348436.410, detail: 
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:450 topic_dtor: Topic 'channel:1666348436.410': 0x7fae38005690 destroyed
[2022-10-21 13:33:56] DEBUG[26363]: cel_radius.c:193 radius_log: Unable to create RADIUS record. CEL not recorded!
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:1666348436.411, detail: 
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:1666348436.411': 0x7fae380069c0 created
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348436.411, detail: 
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:450 topic_dtor: Topic 'channel:1666348436.411': 0x7fae380069c0 destroyed
[2022-10-21 13:33:56] DEBUG[26363]: cel_radius.c:193 radius_log: Unable to create RADIUS record. CEL not recorded!
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:1666348436.412, detail: 
[2022-10-21 13:33:56] DEBUG[26362]: cdr.c:1470 cdr_object_finalize: Finalized CDR for PJSIP/proxy-trunk-00000042 - start 1666348436.158917 answer 1666348436.161226 end 1666348436.396819 dur 0.237 bill 0.235 dispo ANSWERED
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:1666348436.412': 0x7fae38008fc0 created
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1666348436.412, detail: 
[2022-10-21 13:33:56] DEBUG[26363]: stasis.c:450 topic_dtor: Topic 'channel:1666348436.412': 0x7fae38008fc0 destroyed
[2022-10-21 13:33:56] DEBUG[26363]: cel_radius.c:193 radius_log: Unable to create RADIUS record. CEL not recorded!
[2022-10-21 13:33:56] DEBUG[26371]: res_pjsip/pjsip_distributor.c:503 distributor: Searching for serializer associated with dialog dlg0x7fae18047b38 for Request msg BYE/cseq=2 (rdata0x7fae78001bb8)
[2022-10-21 13:33:56] DEBUG[26371]: res_pjsip/pjsip_distributor.c:511 distributor: Found serializer pjsip/distributor-0000002c associated with dialog dlg0x7fae18047b38
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip/pjsip_resolver.c:479 sip_resolve: Performing SIP DNS resolution of target 'PROXY_IP'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip/pjsip_resolver.c:506 sip_resolve: Transport type for target 'PROXY_IP' is 'UDP transport'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip/pjsip_resolver.c:527 sip_resolve: Target 'PROXY_IP' is an IP address, skipping resolution
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4738 session_inv_on_tsx_state_changed:  proxy-trunk TSX State: Completed  Inv State: CONFIRMED
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk()'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4379 __print_debug_details: The inv session does NOT have an invite_tsx
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4382 __print_debug_details: The UAS BYE transaction involved in this state change is 0x7fae18028718
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4386 __print_debug_details: The current transaction state is Completed
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4388 __print_debug_details: The transaction state change event is TX_MSG
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is CONFIRMED
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4925 session_inv_on_tsx_state_changed:  Nothing delayed
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4170 session_on_tsx_state:  proxy-trunk TSX State: Completed  Inv State: CONFIRMED
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4175 session_on_tsx_state:  Topology: Pending: (null topology)  Active: (null topology)
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4178 session_on_tsx_state:  
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4620 session_inv_on_state_changed:  proxy-trunk Event: TSX_STATE  Inv State: DISCONNCTD
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk()'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4379 __print_debug_details: The inv session does NOT have an invite_tsx
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4391 __print_debug_details: There is no transaction involved in this state change
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is DISCONNCTD
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4646 session_inv_on_state_changed: proxy-trunk: Source of transaction state change is RX_MSG
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4588 handle_incoming_before_media: proxy-trunk: Received request
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4402 handle_incoming_request:  proxy-trunk: Method is BYE
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4412 handle_incoming_request:  proxy-trunk
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4693 session_inv_on_state_changed:  
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4738 session_inv_on_tsx_state_changed:  proxy-trunk TSX State: Completed  Inv State: DISCONNCTD
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk()'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4379 __print_debug_details: The inv session does NOT have an invite_tsx
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4382 __print_debug_details: The UAS BYE transaction involved in this state change is 0x7fae18028718
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4386 __print_debug_details: The current transaction state is Completed
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4388 __print_debug_details: The transaction state change event is RX_MSG
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is DISCONNCTD
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4925 session_inv_on_tsx_state_changed:  Nothing delayed
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4170 session_on_tsx_state:  proxy-trunk TSX State: Completed  Inv State: DISCONNCTD
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4175 session_on_tsx_state:  Topology: Pending: (null topology)  Active: (null topology)
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4178 session_on_tsx_state:  
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:2975 chan_pjsip_session_end:  proxy-trunk
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:2978 chan_pjsip_session_end:  No channel
[2022-10-21 13:33:56] DEBUG[26371]: res_pjsip/pjsip_distributor.c:503 distributor: Searching for serializer associated with dialog dlg0x7fae18026758 for Request msg ACK/cseq=3 (rdata0x7fae78001bb8)
[2022-10-21 13:33:56] DEBUG[26371]: res_pjsip/pjsip_distributor.c:511 distributor: Found serializer pjsip/distributor-00000022 associated with dialog dlg0x7fae18026758
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4738 session_inv_on_tsx_state_changed:  PJSIP/proxy-trunk-00000043 TSX State: Terminated  Inv State: CONNECTING
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk(PJSIP/proxy-trunk-00000043)'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4379 __print_debug_details: The inv session does NOT have an invite_tsx
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4382 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fae1805b5f8
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4386 __print_debug_details: The current transaction state is Terminated
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4388 __print_debug_details: The transaction state change event is USER
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is CONNECTING
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4925 session_inv_on_tsx_state_changed:  Nothing delayed
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4170 session_on_tsx_state:  PJSIP/proxy-trunk-00000043 TSX State: Terminated  Inv State: CONNECTING
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4175 session_on_tsx_state:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4178 session_on_tsx_state:  
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4620 session_inv_on_state_changed:  PJSIP/proxy-trunk-00000043 Event: RX_MSG  Inv State: CONFIRMED
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_state_changed called on event RX_MSG
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk(PJSIP/proxy-trunk-00000043)'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4379 __print_debug_details: The inv session does NOT have an invite_tsx
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4391 __print_debug_details: There is no transaction involved in this state change
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is CONFIRMED
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4588 handle_incoming_before_media: PJSIP/proxy-trunk-00000043: Received request
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4402 handle_incoming_request:  PJSIP/proxy-trunk-00000043: Method is ACK
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:3244 chan_pjsip_incoming_ack:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: chan_pjsip.c:3252 chan_pjsip_incoming_ack:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4412 handle_incoming_request:  PJSIP/proxy-trunk-00000043
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4693 session_inv_on_state_changed:  
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4225 session_on_rx_request:  PJSIP/proxy-trunk-00000043 Request: ACK 
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4245 session_on_rx_request:  PJSIP/proxy-trunk-00000043 Handled request ACK  ? yes
[2022-10-21 13:33:56] DEBUG[26371]: res_pjsip/pjsip_distributor.c:503 distributor: Searching for serializer associated with dialog dlg0x7fae18047b38 for Response msg 481/BYE/cseq=25100 (rdata0x7fae78001bb8)
[2022-10-21 13:33:56] DEBUG[26371]: res_pjsip/pjsip_distributor.c:511 distributor: Found serializer pjsip/distributor-0000002c associated with dialog dlg0x7fae18047b38
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4193 session_on_rx_response:  proxy-trunk Method: BYE Status: 481
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4195 session_on_rx_response:  
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4738 session_inv_on_tsx_state_changed:  proxy-trunk TSX State: Completed  Inv State: DISCONNCTD
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4357 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4371 __print_debug_details: The state change pertains to the endpoint 'proxy-trunk()'
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4379 __print_debug_details: The inv session does NOT have an invite_tsx
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4382 __print_debug_details: The UAC BYE transaction involved in this state change is 0x7fae1805a508
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4386 __print_debug_details: The current transaction state is Completed
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4388 __print_debug_details: The transaction state change event is RX_MSG
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4393 __print_debug_details: The current inv state is DISCONNCTD
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4455 handle_incoming_response:  proxy-trunk: Response is 481 Call/Transaction Does Not Exist
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_sessASTERISK_IPion.c:4466 handle_incoming_response:  proxy-trunk
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4888 session_inv_on_tsx_state_changed: proxy-trunk: BYE received final response code 481
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4925 session_inv_on_tsx_state_changed:  Nothing delayed
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4170 session_on_tsx_state:  proxy-trunk TSX State: Completed  Inv State: DISCONNCTD
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4175 session_on_tsx_state:  Topology: Pending: (null topology)  Active: (null topology)
[2022-10-21 13:33:56] DEBUG[470]: res_pjsip_session.c:4178 session_on_tsx_state:  
[2022-10-21 13:33:56] DEBUG[759][C-00000022]: pbx.c:2938 pbx_extension_helper: Launching 'MusicOnHold'
[2022-10-21 13:33:56] DEBUG[759][C-00000022]: channel.c:3211 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2022-10-21 13:33:56] DEBUG[759][C-00000022]: channel.c:5752 set_format: Channel PJSIP/proxy-trunk-00000043 setting write format path: slin -> alaw
[2022-10-21 13:33:56] DEBUG[759][C-00000022]: res_musiconhold.c:390 ast_moh_files_next: PJSIP/proxy-trunk-00000043 Opened file 0 '/var/lib/asterisk/moh//macroform-cold_day'
[2022-10-21 13:33:56] DEBUG[759][C-00000022]: res_rtp_asterisk.c:5371 ast_rtp_write: (0x7fae30049450) RTP ooh, format changed from none to alaw
4

Asterisk calls the pjsip_replaces_verify_request function[1][2] to verify the request. This failed, and PJSIP told us to respond with a 603. We don’t use the response they produce as-is because of our implementation, but if you look at the code and maybe tweak things it may provide insight.

[1] SIP Replaces support (RFC 3891 - "Replaces" Header) (2.12)
[2] pjproject/sip_replaces.c at master · pjsip/pjproject · GitHub

5

Actually, there’s only one place in the code that produces a 603[1] which is when the INVITE session/call has been terminated/disconnected already.

[1] pjproject/sip_replaces.c at master · pjsip/pjproject · GitHub

6

Hi jcolp!

Thanks for your reply. Actually while i was posting debug info i noticed that in failed call BYE for initial call comes before invite, so it seems like first call is already terminated at the time INVITE with Replaces comes in some cases. I will look into this and try to hold first call.

Thanks a lot!

7

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