I've seen this happen three times in the wild now. I've been trying to
isolate the source of the issue, but so far it seems like there's not
enough debug output to know why this occurs.
Long story short:
- Start Asterisk
- PJSIP Handles receiving INVITE from ITSP via WAN (Asterisk is behind
NAT). SIP is handled correctly, Asterisk responds OK with RTP media
address of external_media_address
- After 30 minutes to an hour or sometimes months later after startup,
upon receiving INVITE from ITSP via WAN, Asterisk responds OK with
INTERNAL LAN IP instead of external_media_address
- I've observed this occur after 30 minutes from startup with no
configuration changes that were made or any pjsip reloads done during
this period
pjsip
-------------
[global]
endpoint_identifier_order = username,ip,anonymous
[system]
type=system
threadpool_initial_size=30
threadpool_auto_increment=5
threadpool_idle_timeout=0
threadpool_max_size=100
[transport-udp]
type = transport
symmetric_transport = yes
protocol = udp
bind = 0.0.0.0:5060
external_media_address = 152.X.Y.Z
external_signaling_address = 152.X.Y.Z
external_signaling_port = 5060
allow_reload = no
tos = cs3
cos = 3
local_net = 127.0.0.1/24
local_net = 192.168.50.0/24
local_net = 192.168.1.0/24
local_net = 10.3.2.0/24
local_net = 10.20.1.0/24
local_net = 10.10.41.0/24
local_net = 10.5.1.0/24
pjsip_wizard
-------------
[isoft-sr-in-1]
type = wizard
transport = transport-udp
remote_hosts = 192.81.237.20
aor/max_contacts = 1
aor/remove_existing = yes
aor/qualify_frequency = 60
aor/qualify_timeout = 2000
endpoint/ice_support = no
endpoint/disallow = g723,slin,ilbc,lpc10,g729,speex,g726aal2,g722
endpoint/allow = ulaw,alaw,adpcm,gsm
endpoint/direct_media = no
endpoint/force_rport = yes
endpoint/rewrite_contact = yes
endpoint/rtp_keepalive = 30
endpoint/rtp_symmetric = yes
endpoint/rtp_timeout = 60
endpoint/rtp_timeout_hold = 60
endpoint/send_pai = yes
endpoint/send_rpid = yes
endpoint/trust_id_inbound = yes
endpoint/trust_id_outbound = yes
endpoint/trust_connected_line = no
endpoint/send_connected_line = no
endpoint/context = trunkhandler_pbx-sip-t1
Attached sip sessions and debug log... the only thing I found
interesting was finding a lack of a log item
We SHOULD be seeing:
DEBUG[XXXXX] res_pjsip_session.c: (null session): Setting external media
address to 152.X.Y.Z
This message is clearly lacking from the debug session where the
incorrect media address is sent. But there's not enough detail in the
debugs to see why this decision was not made to use external_media_address
By default we use nat settings for all our endpoints, but obviously it's
not required here for an ITSP that has trustworthy media ports in the
SDP. Maybe a bandaid is turning off rewrite_contact for this endpoint?
Going to try that as soon as possible.
Why is external_media_address not being used all of a sudden? Has
anyone else seen this... is this a bug?-------------------------------------------------------------
Calls are normal for an indetermine amount of time
-------------------------------------------------------------
INVITE sip:+12011555432@152.X.Y.Z:5060 SIP/2.0^M
Via: SIP/2.0/UDP 192.81.237.20:5060;branch=z9hG4bK489fe.a7c59e79.0^M
From: "MARK MURAWSKI " <sip:+15181231234@192.81.237.21:5060>;tag=gK0c130ae5^M
To: <sip:+12011555432@152.X.Y.Z>^M
Call-ID: 241982955_121107611@4.55.28.225^M
CSeq: 297441 INVITE^M
Max-Forwards: 69^M
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,OPTIONS^M
Accept: application/sdp, application/isup, application/dtmf, application/dtmf-relay, multipart/mixed^M
Contact: <sip:192.81.237.20;met=8c5.8ccd5e34>^M
Content-Length: 307^M
Content-Disposition: session; handling=required^M
Content-Type: application/sdp^M
P-Asserted-Identity: "MARK MURAWSKI " <sip:+15181231234@192.81.237.21:5060;user=phone>^M
^M
v=0^M
o=Sonus_UAC 800537 120497 IN IP4 4.55.28.225^M
s=SIP Media Capabilities^M
c=IN IP4 4.55.28.198^M
t=0 0^M
m=audio 34046 RTP/AVP 0 8 18 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:18 G729/8000^M
a=fmtp:18 annexb=no^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-15^M
a=sendrecv^M
a=maxptime:20^M
SIP/2.0 100 Trying^M
Via: SIP/2.0/UDP 192.81.237.20:5060;rport=5060;received=192.81.237.20;branch=z9hG4bK489fe.a7c59e79.0^M
Call-ID: 241982955_121107611@4.55.28.225^M
From: "MARK MURAWSKI " <sip:+15181231234@192.81.237.21>;tag=gK0c130ae5^M
To: <sip:+12011555432@152.X.Y.Z>^M
CSeq: 297441 INVITE^M
Server: Asterisk PBX 18.18.0^M
Content-Length: 0^M
SIP/2.0 200 OK^M
Via: SIP/2.0/UDP 192.81.237.20:5060;rport=5060;received=192.81.237.20;branch=z9hG4bK489fe.a7c59e79.0^M
Call-ID: 241982955_121107611@4.55.28.225^M
From: "MARK MURAWSKI " <sip:+15181231234@192.81.237.21>;tag=gK0c130ae5^M
To: <sip:+12011555432@152.X.Y.Z>;tag=1014aa45-e933-4506-bff9-5cba4530019c^M
CSeq: 297441 INVITE^M
Server: Asterisk PBX 18.18.0^M
Contact: <sip:152.X.Y.Z:5060>^M
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER^M
Supported: 100rel, timer, replaces, norefersub^M
Content-Type: application/sdp^M
Content-Length: 255^M
^M
v=0^M
o=- 800537 120499 IN IP4 152.X.Y.Z^M <------- proper external_media_address
s=Asterisk^M
c=IN IP4 152.X.Y.Z^M
t=0 0^M
m=audio 16247 RTP/AVP 0 8 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-16^M
a=ptime:20^M
a=maxptime:150^M
a=sendrecv^M
-------------------------------------------------------------
Calls start failing due to wrong RTP media address sent in OK
-------------------------------------------------------------
INVITE sip:+12011555432@152.X.Y.Z:5060 SIP/2.0^M
Via: SIP/2.0/UDP 192.81.237.20:5060;branch=z9hG4bK47ed.e8b49d54.0^M
From: "MARK MURAWSKI " <sip:+15181231234@192.81.237.21:5060>;tag=fK4d5901e2^M
To: <sip:+12011555432@152.X.Y.Z>^M
Call-ID: 341982999_121407647@4.55.28.225^M
CSeq: 297441 INVITE^M
Max-Forwards: 69^M
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,OPTIONS^M
Accept: application/sdp, application/isup, application/dtmf, application/dtmf-relay, multipart/mixed^M
Contact: <sip:192.81.237.20;met=8c5.8ccd5e34>^M
Content-Length: 307^M
Content-Disposition: session; handling=required^M
Content-Type: application/sdp^M
P-Asserted-Identity: "MARK MURAWSKI " <sip:+15181231234@192.81.237.21:5060;user=phone>^M
^M
v=0^M
o=Sonus_UAC 800537 120497 IN IP4 4.55.28.225^M
s=SIP Media Capabilities^M
c=IN IP4 4.55.28.198^M
t=0 0^M
m=audio 34046 RTP/AVP 0 8 18 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:18 G729/8000^M
a=fmtp:18 annexb=no^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-15^M
a=sendrecv^M
a=maxptime:20^M
SIP/2.0 100 Trying^M
Via: SIP/2.0/UDP 192.81.237.20:5060;rport=5060;received=192.81.237.20;branch=z9hG4bK47ed.e8b49d54.0^M
Call-ID: 341982999_121407647@4.55.28.225^M
From: "MARK MURAWSKI " <sip:+15181231234@192.81.237.21>;tag=fK4d5901e2^M
To: <sip:+12011555432@152.X.Y.Z>^M
CSeq: 297441 INVITE^M
Server: Asterisk PBX 18.18.0^M
Content-Length: 0^M
SIP/2.0 200 OK^M
Via: SIP/2.0/UDP 192.81.237.20:5060;rport=5060;received=192.81.237.20;branch=z9hG4bK47ed.e8b49d54.0^M
Call-ID: 341982999_121407647@4.55.28.225^M
From: "MARK MURAWSKI " <sip:+15181231234@192.81.237.21>;tag=fK4d5901e2^M
To: <sip:+12011555432@152.X.Y.Z>;tag=5614aa83-e533-7511-faa3-6dae6590114e^M
CSeq: 297441 INVITE^M
Server: Asterisk PBX 18.18.0^M
Contact: <sip:192.168.1.191:5060>^M
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER^M
Supported: 100rel, timer, replaces, norefersub^M
Content-Type: application/sdp^M
Content-Length: 255^M
^M
v=0^M
o=- 800537 120499 IN IP4 192.168.1.191^M <------ Incorrect external_media_address
s=Asterisk^M
c=IN IP4 192.168.1.191^M
t=0 0^M
m=audio 16888 RTP/AVP 0 8 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-16^M
a=ptime:20^M
a=maxptime:150^M
a=sendrecv^M
---------------------------
Failed call with core debug
---------------------------
[2023-08-17 08:56:32.920-0400] DEBUG[3760] res_pjsip/pjsip_message_filter.c: Set transport 'transport-udp' on INVITE from 192.81.237.20:0
[2023-08-17 08:56:32.920-0400] DEBUG[3760] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=357905 (rdata0x7f9150001cf8)
[2023-08-17 08:56:32.920-0400] DEBUG[3760] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000006a to use for Request msg INVITE/cseq=357905 (rdata0x7f9150001cf8)
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '+15181231234' domain '192.81.237.21'
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '+15181231234' domain '192.81.237.21'
[2023-08-17 08:56:32.920-0400] DEBUG[3726] netsock2.c: Splitting '192.81.237.20' into...
[2023-08-17 08:56:32.920-0400] DEBUG[3726] netsock2.c: ...host '192.81.237.20' and port ''.
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_endpoint_identifier_ip.c: Source address 192.81.237.20:5060 does not match identify 'isoft-sr-out-1-identify'
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_endpoint_identifier_ip.c: Source address 192.81.237.20:5060 does not match identify 'isoft-vit-out-1-identify'
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_endpoint_identifier_ip.c: Source address 192.81.237.20:5060 does not match identify 'localhost-identify'
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_endpoint_identifier_ip.c: Source address 192.81.237.20:5060 matches identify 'isoft-sr-in-1-identify'
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_endpoint_identifier_ip.c: Identify 'isoft-sr-in-1-identify' SIP message matched to endpoint isoft-sr-in-1
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_session.c: (null session) Request: INVITE
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_session.c: Request:
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000006a to use for Request msg INVITE/cseq=357905 (rdata0x7f9150058848)
[2023-08-17 08:56:32.920-0400] DEBUG[3726] chan_pjsip.c: isoft-sr-in-1
[2023-08-17 08:56:32.920-0400] DEBUG[3726] chan_pjsip.c: Direct media no glare mitigation
[2023-08-17 08:56:32.920-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Call (UDP:192.81.237.20:5060) to extension '+12011555432' sending 100 Trying
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Method is INVITE, Response is 100 Trying
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1 Event: TSX_STATE Inv State: INCOMING
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: The state change pertains to the endpoint 'isoft-sr-in-1()'
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f911c639e48)
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: There is no transaction involved in this state change
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: The current inv state is INCOMING
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Source of transaction state change is TX_MSG
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c:
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1 TSX State: Proceeding Inv State: INCOMING
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: The state change pertains to the endpoint 'isoft-sr-in-1()'
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f911c639e48)
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f911c639e48
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: The current transaction state is Proceeding
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: The transaction state change event is TX_MSG
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: The current inv state is INCOMING
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: Nothing delayed
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1 TSX State: Proceeding Inv State: INCOMING
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: Topology: Pending: (null topology) Active: (null topology)
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c:
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Media count: 1
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Processing stream 0
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Using audio-0 for new stream name
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Using new stream 0:audio-0:audio:sendrecv (nothing)
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1 Adding position 0
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: Creating new media session
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: Setting media session as default for audio
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: Done
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: isoft-sr-in-1
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: Splitting '4.55.78.19' into...
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: ...host '4.55.78.19' and port ''.
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: Splitting '0.0.0.0' into...
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: ...host '0.0.0.0' and port ''.
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: Transport transport-udp bound to 0.0.0.0: Using it for RTP media.
[2023-08-17 08:56:32.921-0400] DEBUG[3726] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f911c6d0a20'
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) RTP allocated port 16374
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) ICE creating session 0.0.0.0:16374 (16374)
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) ICE create
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) ICE add system candidates
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: Splitting '192.168.1.191' into...
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: ...host '192.168.1.191' and port ''.
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) ICE add candidate: 192.168.1.191:16374, 2130706431
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: Splitting '192.168.50.1' into...
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: ...host '192.168.50.1' and port ''.
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) ICE add candidate: 192.168.50.1:16374, 2130706431
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: Splitting '10.1.2.86' into...
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: ...host '10.1.2.86' and port ''.
[2023-08-17 08:56:32.921-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) ICE add candidate: 10.1.2.86:16374, 2130706431
[2023-08-17 08:56:32.921-0400] DEBUG[3726] netsock2.c: Splitting '10.3.2.86' into...
[2023-08-17 08:56:32.922-0400] DEBUG[3726] netsock2.c: ...host '10.3.2.86' and port ''.
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) ICE add candidate: 10.3.2.86:16374, 2130706431
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: RTP instance '0x7f911c6d0a20' is setup and ready to go
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) ICE stopped
[2023-08-17 08:56:32.922-0400] DEBUG[3726] netsock2.c: Splitting 'pbx' into...
[2023-08-17 08:56:32.922-0400] DEBUG[3726] netsock2.c: ...host 'pbx' and port ''.
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_rtp_asterisk.c: () RTCP setup on RTP instance
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: isoft-sr-in-1
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: isoft-sr-in-1
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f9114949ed0
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f9114949ed0
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f9114949ed0
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_sdp_rtp.c:
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session/pjsip_session_caps.c: 'isoft-sr-in-1' Caps for incoming audio call with pref 'local' - remote: (ulaw|alaw|g729) local: (ulaw|alaw|adpcm|gsm) joint: (ulaw|alaw)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f911c6b7218) from 0x7f9114949ed0 to 0x7f9114949ed0
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7f911c591678) from 0x7f9114949ed0 to 0x7f9114949ed0
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7f911c8de078) from 0x7f9114949ed0 to 0x7f9114949ed0
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x7f911c6818b8) from 0x7f9114949ed0 to 0x7f9114949ed0
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Copying rx payload mapping 0 (0x7f911c6b7218) from 0x7f9114949ed0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Copying rx payload mapping 8 (0x7f911c591678) from 0x7f9114949ed0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Copying rx payload mapping 18 (0x7f911c8de078) from 0x7f9114949ed0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Copying rx payload mapping 101 (0x7f911c6818b8) from 0x7f9114949ed0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Copying tx payload mapping 0 (0x7f911c6b7218) from 0x7f9114949ed0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Copying tx payload mapping 8 (0x7f911c591678) from 0x7f9114949ed0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Copying tx payload mapping 18 (0x7f911c8de078) from 0x7f9114949ed0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.922-0400] DEBUG[3726] rtp_engine.c: Copying tx payload mapping 101 (0x7f911c6818b8) from 0x7f9114949ed0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_sdp_rtp.c:
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_sdp_rtp.c:
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Media stream 0:audio-0:audio:sendrecv (ulaw|alaw) handled by audio
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Done with stream 0:audio-0:audio:sendrecv (ulaw|alaw)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Handled? yes
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Processing streams
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Processing stream 0:audio-0:audio:sendrecv (ulaw|alaw)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1 Adding position 0
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: Using existing media_session
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1 Stream: 0:audio-0:audio:sendrecv (ulaw|alaw)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: isoft-sr-in-1 Type: audio 0:audio-0:audio:sendrecv (ulaw|alaw)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) RTCP ignoring duplicate property
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: RC: 1
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: Had handler
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Stream 0:audio-0:audio:sendrecv (ulaw|alaw) added
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Done with 0:audio-0:audio:sendrecv (ulaw|alaw)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Adding bundle groups (if available)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Copying connection details
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Processing media 0
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Media 0 reset
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_session.c: isoft-sr-in-1: Method is INVITE
[2023-08-17 08:56:32.922-0400] DEBUG[3726] chan_pjsip.c: isoft-sr-in-1
[2023-08-17 08:56:32.922-0400] DEBUG[3726] chan_pjsip.c: isoft-sr-in-1
[2023-08-17 08:56:32.922-0400] DEBUG[3726] channel_internal_api.c: <initializing>: Formats: (none)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] channel_internal_api.c: Channel is being initialized or destroyed
[2023-08-17 08:56:32.922-0400] DEBUG[3726] stasis.c: Creating topic. name: channel:1692276992.800, detail:
[2023-08-17 08:56:32.922-0400] DEBUG[3726] stasis.c: Topic 'channel:1692276992.800': 0x7f911c1559b0 created
[2023-08-17 08:56:32.922-0400] DEBUG[3726] channel.c: Channel 0x7f911c7fd540 'PJSIP/isoft-sr-in-1-0000012c' allocated
[2023-08-17 08:56:32.922-0400] DEBUG[3726] chan_pjsip.c: Topology: <0:audio-0:audio:sendrecv (ulaw|alaw)> Formats: (ulaw|alaw|adpcm|gsm)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] chan_pjsip.c: Compatible? yes
[2023-08-17 08:56:32.922-0400] DEBUG[3726] channel_internal_api.c: PJSIP/isoft-sr-in-1-0000012c: MultistreamFormats: (ulaw|alaw)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] channel_internal_api.c: Set native formats but not topology
[2023-08-17 08:56:32.922-0400] DEBUG[3726] channel_internal_api.c: PJSIP/isoft-sr-in-1-0000012c: <0:audio-0:audio:sendrecv (ulaw|alaw)>
[2023-08-17 08:56:32.922-0400] DEBUG[3726] channel_internal_api.c: Used provided topology
[2023-08-17 08:56:32.922-0400] DEBUG[3726] chan_pjsip.c:
[2023-08-17 08:56:32.922-0400] DEBUG[3726] chan_pjsip.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.922-0400] DEBUG[3726] channel.c: Added datastore to channel 'PJSIP/isoft-sr-in-1-0000012c', Type: T38 framehook, UID: (null)
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_geolocation.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_geolocation.c: PJSIP/isoft-sr-in-1-0000012c: Message has no Geolocation header
[2023-08-17 08:56:32.922-0400] DEBUG[3726] res_pjsip_geolocation.c: PJSIP/isoft-sr-in-1-0000012c: Endpoint has no geoloc_incoming_call_profile. Done.
[2023-08-17 08:56:32.923-0400] DEBUG[3726] channel.c: Added datastore to channel 'PJSIP/isoft-sr-in-1-0000012c', Type: FEATURE, UID: (null)
[2023-08-17 08:56:32.923-0400] DEBUG[3726] chan_pjsip.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.930-0400] DEBUG[21287][C-00000136] chan_pjsip.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.930-0400] DEBUG[3707] devicestate.c: No provider found, checking channel drivers for PJSIP - isoft-sr-in-1
[2023-08-17 08:56:32.930-0400] DEBUG[3707] devicestate.c: Changing state for PJSIP/isoft-sr-in-1 - state 2 (In use)
[2023-08-17 08:56:32.931-0400] DEBUG[3726] chan_pjsip.c: PJSIP/isoft-sr-in-1-0000012c5A
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: PJSIP/isoft-sr-in-1-0000012c Stream: 0:audio-0:audio:sendrecv (ulaw|alaw)
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) RTCP ignoring duplicate property
[2023-08-17 08:56:32.931-0400] DEBUG[3726] netsock2.c: Splitting '4.55.78.19' into...
[2023-08-17 08:56:32.931-0400] DEBUG[3726] netsock2.c: ...host '4.55.78.19' and port ''.
[2023-08-17 08:56:32.931-0400] DEBUG[3726] acl.c: For destination '4.55.78.19', our source address is '192.168.1.191'.
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) RTCP setting address on RTP instance
[2023-08-17 08:56:32.931-0400] VERBOSE[3726] res_rtp_asterisk.c: 0x7f911c854a90 -- Strict RTP learning after remote address set to: 4.55.78.19:28242
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: PJSIP/isoft-sr-in-1-0000012c ANSWER
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.931-0400] DEBUG[3726] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f911494a0c0
[2023-08-17 08:56:32.931-0400] DEBUG[3726] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f911494a0c0
[2023-08-17 08:56:32.931-0400] DEBUG[3726] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f911494a0c0
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_sdp_rtp.c:
[2023-08-17 08:56:32.931-0400] DEBUG[3726] rtp_engine.c: Copying tx payload mapping 0 (0x7f911c5fd008) from 0x7f911494a0c0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.931-0400] DEBUG[3726] rtp_engine.c: Copying tx payload mapping 8 (0x7f911c009d68) from 0x7f911494a0c0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.931-0400] DEBUG[3726] rtp_engine.c: Copying tx payload mapping 18 (0x7f911c670548) from 0x7f911494a0c0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.931-0400] DEBUG[3726] rtp_engine.c: Copying tx payload mapping 101 (0x7f911c63c968) from 0x7f911494a0c0 to 0x7f911c6d0bf8
[2023-08-17 08:56:32.931-0400] DEBUG[3726] channel_internal_api.c: PJSIP/isoft-sr-in-1-0000012c: MultistreamFormats: (ulaw)
[2023-08-17 08:56:32.931-0400] DEBUG[3726] channel_internal_api.c: Set native formats but not topology
[2023-08-17 08:56:32.931-0400] DEBUG[3726] channel.c: Channel PJSIP/isoft-sr-in-1-0000012c setting read format path: ulaw -> ulaw
[2023-08-17 08:56:32.931-0400] DEBUG[3726] channel.c: Channel PJSIP/isoft-sr-in-1-0000012c setting write format path: ulaw -> ulaw
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_sdp_rtp.c:
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c6d0a20) DTLS - ast_rtp_activate rtp=0x7f911c854a90 - setup and perform DTLS'
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c854a90) DTLS perform handshake - ssl = (nil), setup = 0
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_rtp_asterisk.c: (0x7f911c854a90) DTLS perform handshake - ssl = (nil), setup = 0
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_sdp_rtp.c: Handled
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[2023-08-17 08:56:32.931-0400] DEBUG[3726] channel_internal_api.c: PJSIP/isoft-sr-in-1-0000012c: <0:audio-0:audio:sendrecv (ulaw|alaw)>
[2023-08-17 08:56:32.931-0400] DEBUG[3726] channel_internal_api.c: Used provided topology
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c:
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c: Method is INVITE, Response is 200 OK
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.1.191:5060 (this may be re-written again later)
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c Event: TSX_STATE Inv State: CONNECTING
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: The state change pertains to the endpoint 'isoft-sr-in-1(PJSIP/isoft-sr-in-1-0000012c)'
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f911c639e48)
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: There is no transaction involved in this state change
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: The current inv state is CONNECTING
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c: Source of transaction state change is TX_MSG
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c:
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c TSX State: Completed Inv State: CONNECTING
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: The state change pertains to the endpoint 'isoft-sr-in-1(PJSIP/isoft-sr-in-1-0000012c)'
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f911c639e48)
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f911c639e48
[2023-08-17 08:56:32.931-0400] DEBUG[3726] res_pjsip_session.c: The current transaction state is Completed
[2023-08-17 08:56:32.956-0400] DEBUG[3726] res_pjsip_session.c: The transaction state change event is TX_MSG
[2023-08-17 08:56:32.956-0400] DEBUG[3726] res_pjsip_session.c: The current inv state is CONNECTING
[2023-08-17 08:56:32.956-0400] DEBUG[3726] res_pjsip_session.c: Nothing delayed
[2023-08-17 08:56:32.956-0400] DEBUG[3726] res_pjsip_session.c: PJSIP/isoft-sr-in-1-0000012c TSX State: Completed Inv State: CONNECTING
[2023-08-17 08:56:32.956-0400] DEBUG[3726] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (ulaw|alaw)>
[2023-08-17 08:56:32.956-0400] DEBUG[3726] res_pjsip_session.c:
[2023-08-17 08:56:32.956-0400] DEBUG[3726] chan_pjsip.c:
[2023-08-17 08:56:32.956-0400] DEBUG[21287][C-00000136] chan_pjsip.c:
[2023-08-17 08:56:32.956-0400] DEBUG[21287][C-00000136] chan_pjsip.c: PJSIP/isoft-sr-in-1-0000012c: Indicated Stop generators
[2023-08-17 08:56:32.956-0400] DEBUG[21287][C-00000136] chan_pjsip.c: PJSIP/isoft-sr-in-1-0000012c
--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
Check out the new Asterisk community forum at: https://community.asterisk.org/
New to Asterisk? Start here:
https://wiki.asterisk.org/wiki/display/AST/Getting+Started
asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
http://lists.digium.com/mailman/listinfo/asterisk-users
