Asterisk codec negotiation with SIP provider on incoming call

gistfile1.txt

[Apr  6 20:49:17] Asterisk 16.6.2 built by _pbuild @ amd64-stable.ports.openbsd.org on a amd64 running OpenBSD on 2019-11-22 09:21:53 UTC
[Apr  6 20:49:17] NOTICE[-1] loader.c: 306 modules will be loaded.
[Apr  6 20:49:18] ERROR[-1] res_config_sqlite3.c: Missing config file 'res_config_sqlite3.conf'
[Apr  6 20:49:18] ERROR[-1] config_options.c: Unable to load config file 'statsd.conf'
[Apr  6 20:49:18] NOTICE[-1] res_statsd.c: Could not load statsd config; using defaults
[Apr  6 20:49:18] ERROR[-1] config_options.c: Unable to load config file 'udptl.conf'
[Apr  6 20:49:18] NOTICE[-1] udptl.c: Could not load udptl config; using defaults
[Apr  6 20:49:18] ERROR[-1] config_options.c: Unable to load config file 'acl.conf'
[Apr  6 20:49:18] NOTICE[-1] manager.c: Unable to open AMI configuration manager.conf, or configuration is invalid.
[Apr  6 20:49:18] ERROR[-1] config_options.c: Unable to load config file 'features.conf'
[Apr  6 20:49:18] NOTICE[-1] features_config.c: Could not load features config; using defaults
[Apr  6 20:49:18] ERROR[-1] config_options.c: Unable to load config file 'cel.conf'
[Apr  6 20:49:18] NOTICE[-1] cel.c: Failed to process CEL configuration; using defaults
[Apr  6 20:49:18] NOTICE[-1] cdr.c: CDR simple logging enabled.
[Apr  6 20:49:18] WARNING[-1] ccss.c: Could not find valid ccss.conf file. Using cc_max_requests default
[Apr  6 20:49:18] WARNING[-1] ccss.c: Could not find valid ccss.conf file. Using cc_[state]_devstate defaults
[Apr  6 20:49:18] ERROR[-1] res_sorcery_config.c: Unable to load config file 'pjproject.conf'
[Apr  6 20:49:19] ERROR[-1] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[Apr  6 20:49:19] ERROR[-1] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[Apr  6 20:49:19] ERROR[-1] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[Apr  6 20:49:19] ERROR[-1] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[Apr  6 20:49:19] WARNING[-1] res_musiconhold.c: Music on hold 'random' setting is deprecated in 14.  Please use 'sort=random' instead.
[Apr  6 20:49:19] ERROR[-1] res_phoneprov.c: Unable to load config phoneprov.conf
[Apr  6 20:49:19] ERROR[-1] res_phoneprov.c: Unable to load provisioning profiles.
[Apr  6 20:49:19] NOTICE[-1] res_smdi.c: Unable to load config smdi.conf: SMDI disabled
[Apr  6 20:49:19] NOTICE[-1] res_smdi.c: No SMDI interfaces are available to listen on, not starting SMDI listener.
[Apr  6 20:49:19] WARNING[-1] res_stun_monitor.c: Unable to load config res_stun_monitor.conf
[Apr  6 20:49:19] ERROR[-1] config_options.c: Unable to load config file 'xmpp.conf'
[Apr  6 20:49:20] ERROR[-1] chan_iax2.c: Unable to load config iax.conf
[Apr  6 20:49:20] NOTICE[-1] chan_mgcp.c: Unable to load config mgcp.conf, MGCP disabled
[Apr  6 20:49:20] NOTICE[-1] chan_skinny.c: Configuring skinny from skinny.conf
[Apr  6 20:49:20] NOTICE[-1] chan_skinny.c: Unable to load config skinny.conf, Skinny disabled.
[Apr  6 20:49:20] NOTICE[-1] res_fax.c: Configuration file 'res_fax.conf' not found, using default options.
[Apr  6 20:49:20] ERROR[-1] config_options.c: Unable to load config file 'hep.conf'
[Apr  6 20:49:20] ERROR[-1] config_options.c: Unable to load config file 'pjsip_notify.conf'
[Apr  6 20:49:20] ERROR[-1] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[Apr  6 20:49:20] ERROR[-1] config_options.c: Unable to load config file 'ari.conf'
[Apr  6 20:49:20] ERROR[-1] ari/config.c: Error obtaining config from ari.conf
[Apr  6 20:49:20] ERROR[-1] config_options.c: Unable to load config file 'confbridge.conf'
[Apr  6 20:49:20] ERROR[-1] app_confbridge.c: Unable to load config. Not loading module.
[Apr  6 20:49:20] ERROR[-1] config_options.c: Unable to load config file 'agents.conf'
[Apr  6 20:49:20] ERROR[-1] app_agent_pool.c: Unable to load config. Not loading module.
[Apr  6 20:49:20] ERROR[-1] config_options.c: Unable to load config file 'res_parking.conf'
[Apr  6 20:49:20] ERROR[-1] cdr_custom.c: Unable to load cdr_custom.conf. Not logging custom CSV CDRs.
[Apr  6 20:49:20] WARNING[-1] cdr_manager.c: Failed to load configuration file. Module not activated.
[Apr  6 20:49:20] NOTICE[-1] cdr_radius.c: Cannot load radiusclient-ng configuration file /etc/radiusclient-ng/radiusclient.conf.
[Apr  6 20:49:20] WARNING[-1] cdr_sqlite3_custom.c: Failed to load configuration file. Module not activated.
[Apr  6 20:49:20] ERROR[-1] cel_custom.c: Unable to load cel_custom.conf. Not logging CEL to custom CSVs.
[Apr  6 20:49:20] WARNING[-1] cel_manager.c: Failed to load configuration file. CEL manager Module not activated.
[Apr  6 20:49:20] WARNING[-1] cel_sqlite3_custom.c: Failed to load configuration file. Module not activated.
[Apr  6 20:49:20] ERROR[-1] app_amd.c: Configuration file amd.conf missing.
[Apr  6 20:49:21] WARNING[-1] app_festival.c: No such configuration file festival.conf
[Apr  6 20:49:21] WARNING[-1] app_followme.c: No follow me config file (followme.conf), so no follow me
[Apr  6 20:49:21] WARNING[-1] app_minivm.c: Failed to load configuration file. Module activated with default settings.
[Apr  6 20:49:21] ERROR[-1] chan_unistim.c: Unable to load config unistim.conf
[Apr  6 20:49:21] ERROR[-1] pbx_dundi.c: Unable to load config dundi.conf
[Apr  6 20:49:22] NOTICE[-1] pbx_ael.c: File /etc/asterisk/extensions.ael not found; AEL declining load
[Apr  6 20:49:22] NOTICE[-1] app_queue.c: No queuerules.conf file found, queues will not follow penalty rules
[Apr  6 20:49:22] NOTICE[-1] app_queue.c: No call queueing config file (queues.conf), so no call queues
[Apr  6 20:49:22] WARNING[-1] loader.c: Some non-required modules failed to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: res_phoneprov declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: Declined modules which depend on res_phoneprov: res_pjsip_phoneprov_provider
[Apr  6 20:49:22] ERROR[-1] loader.c: res_stun_monitor declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: res_xmpp declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: Declined modules which depend on res_xmpp: chan_motif
[Apr  6 20:49:22] ERROR[-1] loader.c: chan_iax2 declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: chan_skinny declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: res_hep declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: Declined modules which depend on res_hep: res_hep_rtcp, res_hep_pjsip
[Apr  6 20:49:22] ERROR[-1] loader.c: res_pjsip_notify declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: res_ari declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: Declined modules which depend on res_ari: res_ari_applications, res_ari_asterisk, res_ari_device_states, res_ari_endpoints, res_ari_events, res_ari_recordings, res_ari_sounds, res_ari_bridges, res_ari_channels, res_ari_playbacks
[Apr  6 20:49:22] ERROR[-1] loader.c: app_confbridge declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: Declined modules which depend on app_confbridge: app_page
[Apr  6 20:49:22] ERROR[-1] loader.c: app_agent_pool declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: res_parking declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: cdr_manager declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: cdr_radius declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: cdr_sqlite3_custom declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: cel_manager declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: cel_radius declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: cel_sqlite3_custom declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: app_amd declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: app_festival declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: app_followme declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: chan_unistim declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: pbx_dundi declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: app_alarmreceiver declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: pbx_ael declined to load.
[Apr  6 20:49:22] ERROR[-1] loader.c: app_queue declined to load.
[Apr  6 20:49:22] VERBOSE[-1] asterisk.c: Asterisk Ready.
[Apr  6 20:49:23] DEBUG[-1] res_pjsip_outbound_registration.c: Outbound REGISTER attempt 1 to 'sip:${PROVIDER_FQDN}' with client 'sip:${SIP_PHONE}@${PROVIDER_FQDN}'
[Apr  6 20:49:23] DEBUG[-1] res_pjsip_outbound_registration.c: Received REGISTER response 200(OK)
[Apr  6 20:49:23] DEBUG[-1] res_pjsip_outbound_registration.c: Processing REGISTER response 200 from server 'sip:${PROVIDER_FQDN}' for client 'sip:${SIP_PHONE}@${PROVIDER_FQDN}'
[Apr  6 20:49:23] DEBUG[-1] res_pjsip_outbound_registration.c: Outbound registration to 'sip:${PROVIDER_FQDN}' with client 'sip:${SIP_PHONE}@${PROVIDER_FQDN}' successful
[Apr  6 20:49:23] DEBUG[-1] res_pjsip_outbound_registration.c: Scheduling outbound registration to server 'sip:${PROVIDER_FQDN}' from client 'sip:${SIP_PHONE}@${PROVIDER_FQDN}' in 2418 seconds
[Apr  6 20:49:37] VERBOSE[-1] asterisk.c: Remote UNIX connection
[Apr  6 20:49:37] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:49:37] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:49:37] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:49:42] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:49:42] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:50:07] Asterisk 16.6.2 built by _pbuild @ amd64-stable.ports.openbsd.org on a amd64 running OpenBSD on 2019-11-22 09:21:53 UTC
[Apr  6 20:50:07] VERBOSE[-1] loader.c: Reloading module 'logger' (Logger)
[Apr  6 20:50:07] DEBUG[-1] config.c: Parsing /etc/asterisk/logger.conf
[Apr  6 20:50:07] VERBOSE[-1] logger.c: Asterisk Queue Logger restarted
[Apr  6 20:50:18] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:50:18] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:50:18] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:50:18] DEBUG[-1] threadpool.c: Destroying worker thread 7
[Apr  6 20:50:18] DEBUG[-1] threadpool.c: Destroying worker thread 9
[Apr  6 20:50:18] DEBUG[-1] threadpool.c: Destroying worker thread 8
[Apr  6 20:50:19] DEBUG[-1] res_pjsip_registrar.c: Woke up at 1586170219  Interval: 30
[Apr  6 20:50:19] DEBUG[-1] res_pjsip_registrar.c: Expiring 0 contacts
[Apr  6 20:50:20] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:50:20] DEBUG[-1] threadpool.c: Destroying worker thread 10
[Apr  6 20:50:22] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:50:22] DEBUG[-1] threadpool.c: Destroying worker thread 6
[Apr  6 20:50:23] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:50:23] DEBUG[-1] threadpool.c: Destroying worker thread 5
[Apr  6 20:50:49] DEBUG[-1] res_pjsip_registrar.c: Woke up at 1586170249  Interval: 30
[Apr  6 20:50:49] DEBUG[-1] res_pjsip_registrar.c: Expiring 0 contacts
[Apr  6 20:51:19] DEBUG[-1] res_pjsip_registrar.c: Woke up at 1586170279  Interval: 30
[Apr  6 20:51:19] DEBUG[-1] res_pjsip_registrar.c: Expiring 0 contacts
[Apr  6 20:51:49] DEBUG[-1] res_pjsip_registrar.c: Woke up at 1586170309  Interval: 30
[Apr  6 20:51:49] DEBUG[-1] res_pjsip_registrar.c: Expiring 0 contacts
[Apr  6 20:52:19] DEBUG[-1] res_pjsip_registrar.c: Woke up at 1586170339  Interval: 30
[Apr  6 20:52:19] DEBUG[-1] res_pjsip_registrar.c: Expiring 0 contacts
[Apr  6 20:52:49] DEBUG[-1] res_pjsip_registrar.c: Woke up at 1586170369  Interval: 30
[Apr  6 20:52:49] DEBUG[-1] res_pjsip_registrar.c: Expiring 0 contacts
[Apr  6 20:53:19] DEBUG[-1] res_pjsip_registrar.c: Woke up at 1586170399  Interval: 30
[Apr  6 20:53:19] DEBUG[-1] res_pjsip_registrar.c: Expiring 0 contacts
[Apr  6 20:53:27] VERBOSE[-1] res_pjsip_logger.c: <--- Received SIP request (886 bytes) from UDP:${PROVIDER_IP}:5060 --->
INVITE sip:${SIP_PHONE}@${ASTERISK_EXT_IP}:5060 SIP/2.0
Via: SIP/2.0/UDP ${PROVIDER_IP}:5060;branch=z9hG4bKahikqp30d8g7j79t4600.1
From: <sip:${HOME_PHONE}@${UPSTREAM_IP};user=phone>;tag=1760226105-1586170406639-
To: "${PROVIDER_NAME}"<sip:${SIP_PHONE}@${PROVIDER_FQDN}>
Call-ID: BW10532663906042037842825@${UPSTREAM_IP}
CSeq: 663737208 INVITE
Contact: <sip:${HOME_PHONE}@${PROVIDER_IP}:5060;transport=udp>
Supported: 100rel
Allow: ACK,BYE,CANCEL,INFO,INVITE,OPTIONS,PRACK,REFER,NOTIFY
Recv-Info: x-broadworks-client-session-info
Accept: application/media_control+xml,application/sdp,multipart/mixed
Max-Forwards: 69
Content-Type: application/sdp
Content-Length: 228

v=0
o=BroadWorks 795228539 1 IN IP4 ${PROVIDER_IP}
s=-
c=IN IP4 ${PROVIDER_IP}
t=0 0
m=audio 27146 RTP/AVP 8 0 18 106 101
a=rtpmap:106 G.729b/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=bsoft: 1 image udptl t38

[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=663737208 (rdata0x3e0da8fb028)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002e to use for Request msg INVITE/cseq=663737208 (rdata0x3e0da8fb028)
[Apr  6 20:53:27] DEBUG[-1] threadpool.c: Increasing threadpool pjsip/pool's size by 5
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${PROVIDER_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${PROVIDER_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_endpoint_identifier_ip.c: Source address ${PROVIDER_IP}:5060 matches identify 'Provider-identify'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_endpoint_identifier_ip.c: Identify 'Provider-identify' SIP message matched to endpoint Provider-endpoint
[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002e to use for Request msg INVITE/cseq=663737208 (rdata0x3e141e17028)
[Apr  6 20:53:27] VERBOSE[-1] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '${ASTERISK_EXT_IP}'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[Apr  6 20:53:27] VERBOSE[-1] res_pjsip_logger.c: <--- Transmitting SIP response (383 bytes) to UDP:${PROVIDER_IP}:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP ${PROVIDER_IP}:5060;rport=5060;received=${PROVIDER_IP};branch=z9hG4bKahikqp30d8g7j79t4600.1
Call-ID: BW10532663906042037842825@${UPSTREAM_IP}
From: <sip:${HOME_PHONE}@${UPSTREAM_IP};user=phone>;tag=1760226105-1586170406639-
To: "${PROVIDER_NAME}" <sip:${SIP_PHONE}@${PROVIDER_FQDN}>
CSeq: 663737208 INVITE
Server: Asterisk PBX 16.6.2
Content-Length:  0


[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint()'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e1462ff0a8)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current inv state is INCOMING
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint()'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e1462ff0a8)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x3e1462ff0a8
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current transaction state is Proceeding
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current inv state is INCOMING
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${PROVIDER_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${PROVIDER_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_EXT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_EXT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_sdp_rtp.c: Endpoint Provider-endpoint: Binding RTP media to ${ASTERISK_EXT_IP}
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x3e1462ff820'
[Apr  6 20:53:27] DEBUG[-1] res_rtp_asterisk.c: Allocated port 22442 for RTP instance '0x3e1462ff820'
[Apr  6 20:53:27] DEBUG[-1] res_rtp_asterisk.c: Creating ICE session ${ASTERISK_EXT_IP}:22442 (22442) for RTP instance '0x3e1462ff820'
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_INT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_INT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_INT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_INT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_EXT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_EXT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_EXT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_EXT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: RTP instance '0x3e1462ff820' is setup and ready to go
[Apr  6 20:53:27] DEBUG[-1] acl.c: Attached to given IP address
[Apr  6 20:53:27] DEBUG[-1] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x3e1462ff820'
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Setting tx payload type 8 based on m type on 0x3e0c57802e0
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Setting tx payload type 0 based on m type on 0x3e0c57802e0
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Setting tx payload type 18 based on m type on 0x3e0c57802e0
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x3e0eef56fd8) from 0x3e0c57802e0 to 0x3e0c57802e0
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x3e128cf4998) from 0x3e0c57802e0 to 0x3e0c57802e0
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x3e0ddd465d8) from 0x3e0c57802e0 to 0x3e0c57802e0
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x3e19841d618) from 0x3e0c57802e0 to 0x3e0c57802e0
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Copying rx payload mapping 0 (0x3e0eef56fd8) from 0x3e0c57802e0 to 0x3e1462ffb78
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Copying rx payload mapping 8 (0x3e128cf4998) from 0x3e0c57802e0 to 0x3e1462ffb78
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Copying rx payload mapping 18 (0x3e0ddd465d8) from 0x3e0c57802e0 to 0x3e1462ffb78
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Copying rx payload mapping 101 (0x3e19841d618) from 0x3e0c57802e0 to 0x3e1462ffb78
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 0 (0x3e0eef56fd8) from 0x3e0c57802e0 to 0x3e1462ffb78
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 8 (0x3e128cf4998) from 0x3e0c57802e0 to 0x3e1462ffb78
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 18 (0x3e0ddd465d8) from 0x3e0c57802e0 to 0x3e1462ffb78
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 101 (0x3e19841d618) from 0x3e0c57802e0 to 0x3e1462ffb78
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Media stream 'audio' handled by audio
[Apr  6 20:53:27] DEBUG[-1] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x3e1462ff820'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Method is INVITE
[Apr  6 20:53:27] DEBUG[-1] stasis.c: Creating topic. name: channel:1586170407.0, detail: 
[Apr  6 20:53:27] DEBUG[-1] stasis.c: Topic 'channel:1586170407.0': 0x3e0da373920 created
[Apr  6 20:53:27] DEBUG[-1] stasis.c: Creating topic. name: cache:16/channel:1586170407.0, detail: 
[Apr  6 20:53:27] DEBUG[-1] stasis.c: Topic 'cache:16/channel:1586170407.0': 0x3e12253a3a0 created
[Apr  6 20:53:27] DEBUG[-1] channel.c: Channel 0x3e0d64cf490 'PJSIP/Provider-endpoint-00000000' allocated
[Apr  6 20:53:27] DEBUG[-1] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/Provider-endpoint-00000000
[Apr  6 20:53:27] DEBUG[-1][C-00000001] pbx.c: Launching 'Dial'
[Apr  6 20:53:27] VERBOSE[-1][C-00000001] pbx.c: Executing [${SIP_PHONE}@Provider-Incoming:1] Dial("PJSIP/Provider-endpoint-00000000", "PJSIP/${SOFTPHONE_USER}") in new stack
[Apr  6 20:53:27] DEBUG[-1] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Apr  6 20:53:27] DEBUG[-1] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr  6 20:53:27] DEBUG[-1] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[Apr  6 20:53:27] DEBUG[-1] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr  6 20:53:27] DEBUG[-1] config.c: extract uint from [0] in [0, 86400] gives [0](0)
[Apr  6 20:53:27] DEBUG[-1][C-00000001] stasis.c: Creating topic. name: channel:1586170407.1, detail: 
[Apr  6 20:53:27] DEBUG[-1][C-00000001] stasis.c: Topic 'channel:1586170407.1': 0x3e13b3cd2a0 created
[Apr  6 20:53:27] DEBUG[-1][C-00000001] stasis.c: Creating topic. name: cache:17/channel:1586170407.1, detail: 
[Apr  6 20:53:27] DEBUG[-1][C-00000001] stasis.c: Topic 'cache:17/channel:1586170407.1': 0x3e11fd8c220 created
[Apr  6 20:53:27] DEBUG[-1][C-00000001] channel.c: Channel 0x3e193b05490 'PJSIP/${SOFTPHONE_USER}-00000001' allocated
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_INT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_INT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_sdp_rtp.c: Endpoint ${SOFTPHONE_USER}: Binding RTP media to ${ASTERISK_INT_IP}
[Apr  6 20:53:27] VERBOSE[-1][C-00000001] app_dial.c: Called PJSIP/${SOFTPHONE_USER}
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x3e0d64d2820'
[Apr  6 20:53:27] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/${SOFTPHONE_USER}-00000001 setting read format path: alaw -> alaw
[Apr  6 20:53:27] DEBUG[-1] res_rtp_asterisk.c: Allocated port 16750 for RTP instance '0x3e0d64d2820'
[Apr  6 20:53:27] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/Provider-endpoint-00000000 setting write format path: alaw -> alaw
[Apr  6 20:53:27] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/Provider-endpoint-00000000 setting read format path: alaw -> alaw
[Apr  6 20:53:27] DEBUG[-1] res_rtp_asterisk.c: Creating ICE session ${ASTERISK_INT_IP}:16750 (16750) for RTP instance '0x3e0d64d2820'
[Apr  6 20:53:27] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/${SOFTPHONE_USER}-00000001 setting write format path: alaw -> alaw
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_INT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_INT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_INT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_INT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_EXT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_EXT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: Splitting '${ASTERISK_EXT_IP}' into...
[Apr  6 20:53:27] DEBUG[-1] netsock2.c: ...host '${ASTERISK_EXT_IP}' and port ''.
[Apr  6 20:53:27] DEBUG[-1] rtp_engine.c: RTP instance '0x3e0d64d2820' is setup and ready to go
[Apr  6 20:53:27] DEBUG[-1] acl.c: Attached to given IP address
[Apr  6 20:53:27] DEBUG[-1] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x3e0d64d2820'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Method is INVITE
[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '${SOFTPHONE_IP}'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_resolver.c: Transport type for target '${SOFTPHONE_IP}' is 'UDP'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_resolver.c: Target '${SOFTPHONE_IP}' is an IP address, skipping resolution
[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to ${ASTERISK_INT_IP}:5060 (this may be re-written again later)
[Apr  6 20:53:27] VERBOSE[-1] res_pjsip_logger.c: <--- Transmitting SIP request (1034 bytes) to UDP:${SOFTPHONE_IP}:5060 --->
INVITE sip:${SOFTPHONE_USER}@${SOFTPHONE_IP} SIP/2.0
Via: SIP/2.0/UDP ${ASTERISK_INT_IP}:5060;rport;branch=z9hG4bKPj1c74a20d-28e2-494d-a16a-48cac853b53d
From: <sip:${HOME_PHONE}@${ASTERISK_EXT_IP}>;tag=e971c236-0ff4-4aa8-9541-f2331a066ff4
To: <sip:${SOFTPHONE_USER}@${SOFTPHONE_IP}>
Contact: <sip:asterisk@${ASTERISK_INT_IP}:5060>
Call-ID: b48f0df2-15fa-457a-8ca5-eafce2e9ab2d
CSeq: 9077 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: Asterisk PBX 16.6.2
Content-Type: application/sdp
Content-Length:   363

v=0
o=- 348333269 348333269 IN IP4 ${ASTERISK_INT_IP}
s=Asterisk
c=IN IP4 ${ASTERISK_INT_IP}
t=0 0
m=audio 16750 RTP/AVP 8 0 9 97 111 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:97 iLBC/8000
a=[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}(PJSIP/${SOFTPHONE_USER}-00000001)'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e0d64cb8a8)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current inv state is CALLING
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}(PJSIP/${SOFTPHONE_USER}-00000001)'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e0d64cb8a8)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x3e0d64cb8a8
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current transaction state is Calling
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current inv state is CALLING
[Apr  6 20:53:27] VERBOSE[-1] res_pjsip_logger.c: <--- Received SIP response (374 bytes) from UDP:${SOFTPHONE_IP}:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP ${ASTERISK_INT_IP}:5060;received=${ASTERISK_INT_IP};rport=5060;branch=z9hG4bKPj1c74a20d-28e2-494d-a16a-48cac853b53d
To: <sip:${SOFTPHONE_USER}@${SOFTPHONE_IP}>
From: <sip:${HOME_PHONE}@${ASTERISK_EXT_IP}>;tag=e971c236-0ff4-4aa8-9541-f2331a066ff4
Call-ID: b48f0df2-15fa-457a-8ca5-eafce2e9ab2d
CSeq: 9077 INVITE
Server: Twinkle/1.10.1
Content-Length: 0


[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x3e0e63fb0a8 for Response msg 100/INVITE/cseq=9077 (rdata0x3e0da8fb028)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/${SOFTPHONE_USER}-00000063 associated with dialog dlg0x3e0e63fb0a8
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}(PJSIP/${SOFTPHONE_USER}-00000001)'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e0d64cb8a8)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x3e0d64cb8a8
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current transaction state is Proceeding
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The transaction state change event is RX_MSG
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current inv state is CALLING
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Received response
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Response is 100 Trying
[Apr  6 20:53:27] VERBOSE[-1] res_pjsip_logger.c: <--- Received SIP response (426 bytes) from UDP:${SOFTPHONE_IP}:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP ${ASTERISK_INT_IP}:5060;received=${ASTERISK_INT_IP};rport=5060;branch=z9hG4bKPj1c74a20d-28e2-494d-a16a-48cac853b53d
To: <sip:${SOFTPHONE_USER}@${SOFTPHONE_IP}>;tag=fjagv
From: <sip:${HOME_PHONE}@${ASTERISK_EXT_IP}>;tag=e971c236-0ff4-4aa8-9541-f2331a066ff4
Call-ID: b48f0df2-15fa-457a-8ca5-eafce2e9ab2d
CSeq: 9077 INVITE
Contact: <sip:${SOFTPHONE_USER}@${SOFTPHONE_IP}>
Server: Twinkle/1.10.1
Content-Length: 0


[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x3e0e63fb0a8 for Response msg 180/INVITE/cseq=9077 (rdata0x3e0da8fb028)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/${SOFTPHONE_USER}-00000063 associated with dialog dlg0x3e0e63fb0a8
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}(PJSIP/${SOFTPHONE_USER}-00000001)'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e0d64cb8a8)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current inv state is EARLY
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Received response
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Response is 180 Ringing
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:27] VERBOSE[-1][C-00000001] app_dial.c: PJSIP/${SOFTPHONE_USER}-00000001 is ringing
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}(PJSIP/${SOFTPHONE_USER}-00000001)'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e0d64cb8a8)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x3e0d64cb8a8
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current transaction state is Proceeding
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The transaction state change event is RX_MSG
[Apr  6 20:53:27] DEBUG[-1] devicestate.c: No provider found, checking channel drivers for PJSIP - ${SOFTPHONE_USER}
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current inv state is EARLY
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Received response
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Response is 180 Ringing
[Apr  6 20:53:27] DEBUG[-1] devicestate.c: Changing state for PJSIP/${SOFTPHONE_USER} - state 6 (Ringing)
[Apr  6 20:53:27] DEBUG[-1] devicestate.c: No provider found, checking channel drivers for PJSIP - Provider-endpoint
[Apr  6 20:53:27] DEBUG[-1] devicestate.c: Changing state for PJSIP/Provider-endpoint - state 2 (In use)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing
[Apr  6 20:53:27] VERBOSE[-1][C-00000001] app_dial.c: PJSIP/${SOFTPHONE_USER}-00000001 is ringing
[Apr  6 20:53:27] DEBUG[-1] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to ${ASTERISK_EXT_IP}:5060 (this may be re-written again later)
[Apr  6 20:53:27] VERBOSE[-1] res_pjsip_logger.c: <--- Transmitting SIP response (573 bytes) to UDP:${PROVIDER_IP}:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP ${PROVIDER_IP}:5060;rport=5060;received=${PROVIDER_IP};branch=z9hG4bKahikqp30d8g7j79t4600.1
Call-ID: BW10532663906042037842825@${UPSTREAM_IP}
From: <sip:${HOME_PHONE}@${UPSTREAM_IP};user=phone>;tag=1760226105-1586170406639-
To: "${PROVIDER_NAME}" <sip:${SIP_PHONE}@${PROVIDER_FQDN}>;tag=fc022f98-532a-4236-b938-f906dfe82df6
CSeq: 663737208 INVITE
Server: Asterisk PBX 16.6.2
Contact: <sip:${ASTERISK_EXT_IP}:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Content-Length:  0


[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint(PJSIP/Provider-endpoint-00000000)'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e1462ff0a8)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current inv state is EARLY
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint(PJSIP/Provider-endpoint-00000000)'
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e1462ff0a8)
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x3e1462ff0a8
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current transaction state is Proceeding
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr  6 20:53:27] DEBUG[-1] res_pjsip_session.c: The current inv state is EARLY
[Apr  6 20:53:30] VERBOSE[-1] res_pjsip_logger.c: <--- Received SIP response (777 bytes) from UDP:${SOFTPHONE_IP}:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP ${ASTERISK_INT_IP}:5060;received=${ASTERISK_INT_IP};rport=5060;branch=z9hG4bKPj1c74a20d-28e2-494d-a16a-48cac853b53d
To: <sip:${SOFTPHONE_USER}@${SOFTPHONE_IP}>;tag=fjagv
From: <sip:${HOME_PHONE}@${ASTERISK_EXT_IP}>;tag=e971c236-0ff4-4aa8-9541-f2331a066ff4
Call-ID: b48f0df2-15fa-457a-8ca5-eafce2e9ab2d
CSeq: 9077 INVITE
Contact: <sip:${SOFTPHONE_USER}@${SOFTPHONE_IP}>
Content-Type: application/sdp
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
Server: Twinkle/1.10.1
Supported: replaces,norefersub
Content-Length: 211

v=0
o=twinkle 1646086557 1883097680 IN IP4 ${SOFTPHONE_IP}
s=-
c=IN IP4 ${SOFTPHONE_IP}
t=0 0
m=audio 8000 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

[Apr  6 20:53:30] DEBUG[-1] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x3e0e63fb0a8 for Response msg 200/INVITE/cseq=9077 (rdata0x3e0da8fb028)
[Apr  6 20:53:30] DEBUG[-1] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/${SOFTPHONE_USER}-00000063 associated with dialog dlg0x3e0e63fb0a8
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}(PJSIP/${SOFTPHONE_USER}-00000001)'
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e0d64cb8a8)
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The current inv state is CONNECTING
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Received response
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Response is 200 OK
[Apr  6 20:53:30] VERBOSE[-1][C-00000001] app_dial.c: PJSIP/${SOFTPHONE_USER}-00000001 answered PJSIP/Provider-endpoint-00000000
[Apr  6 20:53:30] DEBUG[-1] devicestate.c: No provider found, checking channel drivers for PJSIP - ${SOFTPHONE_USER}
[Apr  6 20:53:30] DEBUG[-1] devicestate.c: Changing state for PJSIP/${SOFTPHONE_USER} - state 2 (In use)
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Apr  6 20:53:30] DEBUG[-1] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x3e0d64d2820'
[Apr  6 20:53:30] DEBUG[-1] netsock2.c: Splitting '${SOFTPHONE_IP}' into...
[Apr  6 20:53:30] DEBUG[-1] netsock2.c: ...host '${SOFTPHONE_IP}' and port ''.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/${SOFTPHONE_USER}-00000001 setting read format path: alaw -> alaw
[Apr  6 20:53:30] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/Provider-endpoint-00000000 setting write format path: alaw -> alaw
[Apr  6 20:53:30] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/Provider-endpoint-00000000 setting read format path: alaw -> alaw
[Apr  6 20:53:30] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/${SOFTPHONE_USER}-00000001 setting write format path: alaw -> alaw
[Apr  6 20:53:30] DEBUG[-1] acl.c: For destination '${SOFTPHONE_IP}', our source address is '${ASTERISK_INT_IP}'.
[Apr  6 20:53:30] DEBUG[-1] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x3e0d64d2820'
[Apr  6 20:53:30] DEBUG[-1] devicestate.c: No provider found, checking channel drivers for PJSIP - Provider-endpoint
[Apr  6 20:53:30] VERBOSE[-1] res_rtp_asterisk.c: 0x3e0d64d4000 -- Strict RTP learning after remote address set to: ${SOFTPHONE_IP}:8000
[Apr  6 20:53:30] DEBUG[-1] devicestate.c: Changing state for PJSIP/Provider-endpoint - state 2 (In use)
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Setting tx payload type 8 based on m type on 0x3e0c577fc30
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 8 (0x3e16229c818) from 0x3e0c577fc30 to 0x3e0d64d2b78
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 101 (0x3e1a771a518) from 0x3e0c577fc30 to 0x3e0d64d2b78
[Apr  6 20:53:30] DEBUG[-1] channel.c: Channel PJSIP/${SOFTPHONE_USER}-00000001 setting read format path: alaw -> alaw
[Apr  6 20:53:30] DEBUG[-1] channel.c: Channel PJSIP/${SOFTPHONE_USER}-00000001 setting write format path: alaw -> alaw
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Apr  6 20:53:30] DEBUG[-1] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x3e1462ff820'
[Apr  6 20:53:30] DEBUG[-1] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '${SOFTPHONE_IP}'
[Apr  6 20:53:30] DEBUG[-1] netsock2.c: Splitting '${PROVIDER_IP}' into...
[Apr  6 20:53:30] DEBUG[-1] res_pjsip/pjsip_resolver.c: Transport type for target '${SOFTPHONE_IP}' is 'UDP'
[Apr  6 20:53:30] DEBUG[-1] netsock2.c: ...host '${PROVIDER_IP}' and port ''.
[Apr  6 20:53:30] DEBUG[-1] res_pjsip/pjsip_resolver.c: Target '${SOFTPHONE_IP}' is an IP address, skipping resolution
[Apr  6 20:53:30] DEBUG[-1] acl.c: For destination '${PROVIDER_IP}', our source address is '${ASTERISK_EXT_IP}'.
[Apr  6 20:53:30] VERBOSE[-1] res_pjsip_logger.c: <--- Transmitting SIP request (402 bytes) to UDP:${SOFTPHONE_IP}:5060 --->
ACK sip:${SOFTPHONE_USER}@${SOFTPHONE_IP} SIP/2.0
Via: SIP/2.0/UDP ${ASTERISK_INT_IP}:5060;rport;branch=z9hG4bKPjd6aa633e-6b40-415a-b80a-b4a4aae7b4bf
From: <sip:${HOME_PHONE}@${ASTERISK_EXT_IP}>;tag=e971c236-0ff4-4aa8-9541-f2331a066ff4
To: <sip:${SOFTPHONE_USER}@${SOFTPHONE_IP}>;tag=fjagv
Call-ID: b48f0df2-15fa-457a-8ca5-eafce2e9ab2d
CSeq: 9077 ACK
Max-Forwards: 70
User-Agent: Asterisk PBX 16.6.2
Content-Length:  0


[Apr  6 20:53:30] DEBUG[-1] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x3e1462ff820'
[Apr  6 20:53:30] VERBOSE[-1] res_rtp_asterisk.c: 0x3e15de64000 -- Strict RTP learning after remote address set to: ${PROVIDER_IP}:27146
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}(PJSIP/${SOFTPHONE_USER}-00000001)'
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e0d64cb8a8)
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The current inv state is CONFIRMED
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}(PJSIP/${SOFTPHONE_USER}-00000001)'
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Setting tx payload type 8 based on m type on 0x3e11815abd0
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x3e0d64cb8a8
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The current transaction state is Terminated
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Setting tx payload type 0 based on m type on 0x3e11815abd0
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The transaction state change event is RX_MSG
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Setting tx payload type 18 based on m type on 0x3e11815abd0
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The current inv state is CONFIRMED
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Received response
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Response is 200 OK
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 0 (0x3e0eef56fd8) from 0x3e11815abd0 to 0x3e1462ffb78
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 8 (0x3e128cf4998) from 0x3e11815abd0 to 0x3e1462ffb78
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 18 (0x3e0ddd465d8) from 0x3e11815abd0 to 0x3e1462ffb78
[Apr  6 20:53:30] DEBUG[-1] rtp_engine.c: Copying tx payload mapping 101 (0x3e16a239b18) from 0x3e11815abd0 to 0x3e1462ffb78
[Apr  6 20:53:30] DEBUG[-1] channel.c: Channel PJSIP/Provider-endpoint-00000000 setting read format path: alaw -> alaw
[Apr  6 20:53:30] DEBUG[-1] channel.c: Channel PJSIP/Provider-endpoint-00000000 setting write format path: alaw -> alaw
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Method is INVITE, Response is 200 OK
[Apr  6 20:53:30] DEBUG[-1] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to ${ASTERISK_EXT_IP}:5060 (this may be re-written again later)
[Apr  6 20:53:30] VERBOSE[-1] res_pjsip_logger.c: <--- Transmitting SIP response (907 bytes) to UDP:${PROVIDER_IP}:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP ${PROVIDER_IP}:5060;rport=5060;received=${PROVIDER_IP};branch=z9hG4bKahikqp30d8g7j79t4600.1
Call-ID: BW10532663906042037842825@${UPSTREAM_IP}
From: <sip:${HOME_PHONE}@${UPSTREAM_IP};user=phone>;tag=1760226105-1586170406639-
To: "${PROVIDER_NAME}" <sip:${SIP_PHONE}@${PROVIDER_FQDN}>;tag=fc022f98-532a-4236-b938-f906dfe82df6
CSeq: 663737208 INVITE
Server: Asterisk PBX 16.6.2
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Contact: <sip:${ASTERISK_EXT_IP}:5060>
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   257

v=0
o=- 795228539 3 IN IP4 ${ASTERISK_EXT_IP}
s=Asterisk
c=IN IP4 ${ASTERISK_EXT_IP}
t=0 0
m=audio 22442 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=send[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint(PJSIP/Provider-endpoint-00000000)'
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e1462ff0a8)
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The current inv state is CONNECTING
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint(PJSIP/Provider-endpoint-00000000)'
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The inv session still has an invite_tsx (0x3e1462ff0a8)
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x3e1462ff0a8
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The current transaction state is Completed
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr  6 20:53:30] DEBUG[-1] res_pjsip_session.c: The current inv state is CONNECTING
[Apr  6 20:53:30] DEBUG[-1][C-00000001] stasis.c: Creating topic. name: bridge:b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e, detail: 
[Apr  6 20:53:30] DEBUG[-1][C-00000001] stasis.c: Topic 'bridge:b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e': 0x3e0dbdaf720 created
[Apr  6 20:53:30] DEBUG[-1][C-00000001] stasis.c: Creating topic. name: cache:18/bridge:b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e, detail: 
[Apr  6 20:53:30] DEBUG[-1][C-00000001] stasis.c: Topic 'cache:18/bridge:b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e': 0x3e10a277920 created
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e' can not use native RTP bridge as two channels are required
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Chose bridge technology simple_bridge
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling simple_bridge technology constructor
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling simple_bridge technology start
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_channel.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) is joining
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_channel.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: pushing 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001)
[Apr  6 20:53:30] VERBOSE[-1][C-00000001] bridge_channel.c: Channel PJSIP/${SOFTPHONE_USER}-00000001 joined 'simple_bridge' basic-bridge <b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e>
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e' can not use native RTP bridge as two channels are required
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Chose bridge technology simple_bridge
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e is already using the new technology.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) is joining simple_bridge technology
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_channel.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) is joining
[Apr  6 20:53:30] DEBUG[-1][C-00000001] channel.c: Dropping duplicate answer!
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_channel.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: pushing 0x3e0dae96420(PJSIP/Provider-endpoint-00000000)
[Apr  6 20:53:30] VERBOSE[-1][C-00000001] bridge_channel.c: Channel PJSIP/Provider-endpoint-00000000 joined 'simple_bridge' basic-bridge <b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e>
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Checking compatability for channels 'PJSIP/${SOFTPHONE_USER}-00000001' and 'PJSIP/Provider-endpoint-00000000'
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Chose bridge technology native_rtp
[Apr  6 20:53:30] VERBOSE[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: switching from simple_bridge technology to native_rtp
[Apr  6 20:53:30] DEBUG[-1] cdr.c: Finalized CDR for PJSIP/${SOFTPHONE_USER}-00000001 - start 1586170407.222595 answer 1586170410.900306 end 1586170410.907350 dispo ANSWERED
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling native_rtp technology constructor
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: moving 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) to dummy bridge temporarily
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) is leaving simple_bridge technology (dummy)
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling simple_bridge technology stop
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) is joining native_rtp technology
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Channel 'PJSIP/Provider-endpoint-00000000' is joining bridge tech
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Attaching hook data 0x3e0f2411d40 to 'PJSIP/Provider-endpoint-00000000'
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) is joining native_rtp technology
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Channel 'PJSIP/${SOFTPHONE_USER}-00000001' is joining bridge tech
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Attaching hook data 0x3e0f2411800 to 'PJSIP/${SOFTPHONE_USER}-00000001'
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Tech starting 'PJSIP/Provider-endpoint-00000000' and 'PJSIP/${SOFTPHONE_USER}-00000001' with target 'none'
[Apr  6 20:53:30] VERBOSE[-1][C-00000001] bridge_native_rtp.c: Locally RTP bridged 'PJSIP/Provider-endpoint-00000000' and 'PJSIP/${SOFTPHONE_USER}-00000001' in stack
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling native_rtp technology start
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling simple_bridge technology destructor
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Checking compatability for channels 'PJSIP/Provider-endpoint-00000000' and 'PJSIP/${SOFTPHONE_USER}-00000001'
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Chose bridge technology native_rtp
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e is already using the new technology.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Checking compatability for channels 'PJSIP/Provider-endpoint-00000000' and 'PJSIP/${SOFTPHONE_USER}-00000001'
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Chose bridge technology native_rtp
[Apr  6 20:53:30] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e is already using the new technology.
[Apr  6 20:53:30] DEBUG[-1][C-00000001] res_rtp_asterisk.c: Got RTCP report of 36 bytes from ${SOFTPHONE_IP}:8001
[Apr  6 20:53:31] VERBOSE[-1][C-00000001] res_rtp_asterisk.c: 0x3e15de64000 -- Strict RTP switching to RTP target address ${PROVIDER_IP}:27146 as source
[Apr  6 20:53:31] DEBUG[-1][C-00000001] res_rtp_asterisk.c: Unsupported payload type received 
[Apr  6 20:53:31] DEBUG[-1][C-00000001] chan_pjsip.c: Oooh, got a frame with format of g729 on channel 'PJSIP/Provider-endpoint-00000000' when we're sending 'alaw', switching to match
[Apr  6 20:53:31] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/Provider-endpoint-00000000 setting write format path: alaw -> g729
[Apr  6 20:53:31] WARNING[-1][C-00000001] translate.c: No translator path: (ending codec is not valid)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/Provider-endpoint-00000000 setting read format path: alaw -> g729
[Apr  6 20:53:31] WARNING[-1][C-00000001] translate.c: No translator path: (ending codec is not valid)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/Provider-endpoint-00000000 setting read format path: g729 -> g729
[Apr  6 20:53:31] DEBUG[-1][C-00000001] channel.c: Channel PJSIP/${SOFTPHONE_USER}-00000001 changing write format from alaw to g729, native formats (alaw)
[Apr  6 20:53:31] WARNING[-1][C-00000001] channel.c: Unable to find a codec translation path: (g729) -> (alaw)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Checking compatability for channels 'PJSIP/Provider-endpoint-00000000' and 'PJSIP/${SOFTPHONE_USER}-00000001'
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e': Channel codec0 = (g729) is not codec1 = (alaw), cannot native bridge in RTP.
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Chose bridge technology simple_bridge
[Apr  6 20:53:31] VERBOSE[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: switching from native_rtp technology to simple_bridge
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling simple_bridge technology constructor
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: moving 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) to dummy bridge temporarily
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: moving 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) to dummy bridge temporarily
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) is leaving native_rtp technology (dummy)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Channel 'PJSIP/Provider-endpoint-00000000' is leaving bridge tech
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Detaching hook data 0x3e17d62f078 from 'PJSIP/Provider-endpoint-00000000'
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Tech stopping 'PJSIP/Provider-endpoint-00000000' and 'PJSIP/${SOFTPHONE_USER}-00000001' with target 'none'
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/Provider-endpoint-00000000' and 'PJSIP/${SOFTPHONE_USER}-00000001' - media will flow through Asterisk core
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Destroying channel tech_pvt data 0x3e0f2411d40
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) is leaving native_rtp technology (dummy)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Channel 'PJSIP/${SOFTPHONE_USER}-00000001' is leaving bridge tech
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Bridge 'b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e'.  Detaching hook data 0x3e17d62fff8 from 'PJSIP/${SOFTPHONE_USER}-00000001'
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_native_rtp.c: Destroying channel tech_pvt data 0x3e0f2411800
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling native_rtp technology stop
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) is joining simple_bridge technology
[Apr  6 20:53:31] WARNING[-1][C-00000001] channel.c: No path to translate from PJSIP/${SOFTPHONE_USER}-00000001 to PJSIP/Provider-endpoint-00000000
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) failed to join simple_bridge technology (Kicking it out)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_channel.c: Setting 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) state from:0 to:1
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) is joining simple_bridge technology
[Apr  6 20:53:31] WARNING[-1][C-00000001] channel.c: No path to translate from PJSIP/${SOFTPHONE_USER}-00000001 to PJSIP/Provider-endpoint-00000000
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) failed to join simple_bridge technology (Kicking it out)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_channel.c: Setting 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) state from:0 to:1
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling simple_bridge technology start
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling native_rtp technology destructor
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) is joining simple_bridge technology
[Apr  6 20:53:31] WARNING[-1][C-00000001] channel.c: No path to translate from PJSIP/${SOFTPHONE_USER}-00000001 to PJSIP/Provider-endpoint-00000000
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) failed to join simple_bridge technology (Kicking it out)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) is joining simple_bridge technology
[Apr  6 20:53:31] WARNING[-1][C-00000001] channel.c: No path to translate from PJSIP/${SOFTPHONE_USER}-00000001 to PJSIP/Provider-endpoint-00000000
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001) failed to join simple_bridge technology (Kicking it out)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_channel.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: pulling 0x3e0dae96420(PJSIP/Provider-endpoint-00000000)
[Apr  6 20:53:31] VERBOSE[-1][C-00000001] bridge_channel.c: Channel PJSIP/Provider-endpoint-00000000 left 'simple_bridge' basic-bridge <b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e>
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: dissolving bridge with cause 16(Normal Clearing)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: queueing action type:13 sub:1001
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e is dissolved, not performing smart bridge operation.
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e is dissolved, not performing smart bridge operation.
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_channel.c: Bridge is returning 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) to read format alaw
[Apr  6 20:53:31] WARNING[-1][C-00000001] channel.c: Unable to find a codec translation path: (g729) -> (alaw)
[Apr  6 20:53:31] DEBUG[-1] cdr.c: Finalized CDR for PJSIP/Provider-endpoint-00000000 - start 1586170407.217977 answer 1586170410.901465 end 1586170411.070822 dispo ANSWERED
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_channel.c: Bridge failed to return 0x3e0dae96420(PJSIP/Provider-endpoint-00000000) to read format alaw
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge_channel.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: pulling 0x3e1ad8fb820(PJSIP/${SOFTPHONE_USER}-00000001)
[Apr  6 20:53:31] VERBOSE[-1][C-00000001] bridge_channel.c: Channel PJSIP/${SOFTPHONE_USER}-00000001 left 'simple_bridge' basic-bridge <b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e>
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e is dissolved, not performing smart bridge operation.
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: actually destroying basic bridge, nobody wants it anymore
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling basic bridge destructor
[Apr  6 20:53:31] DEBUG[-1][C-00000001] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Apr  6 20:53:31] DEBUG[-1][C-00000001] pbx.c: Spawn extension (Provider-Incoming,${SIP_PHONE},1) exited non-zero on 'PJSIP/Provider-endpoint-00000000'
[Apr  6 20:53:31] VERBOSE[-1][C-00000001] pbx.c: Spawn extension (Provider-Incoming, ${SIP_PHONE}, 1) exited non-zero on 'PJSIP/Provider-endpoint-00000000'
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling simple_bridge technology stop
[Apr  6 20:53:31] DEBUG[-1][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/Provider-endpoint-00000000'
[Apr  6 20:53:31] DEBUG[-1][C-00000001] bridge.c: Bridge b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e: calling simple_bridge technology destructor
[Apr  6 20:53:31] DEBUG[-1][C-00000001] stasis.c: Destroying topic. name: cache:18/bridge:b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e, detail: 
[Apr  6 20:53:31] DEBUG[-1][C-00000001] stasis.c: Topic 'cache:18/bridge:b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e': 0x3e10a277920 destroyed
[Apr  6 20:53:31] DEBUG[-1][C-00000001] stasis.c: Destroying topic. name: bridge:b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e, detail: 
[Apr  6 20:53:31] DEBUG[-1][C-00000001] stasis.c: Topic 'bridge:b8a8351f-cf91-452a-b6c4-f2c2e1e9eb3e': 0x3e0dbdaf720 destroyed
[Apr  6 20:53:31] DEBUG[-1][C-00000001] channel.c: Channel 0x3e0d64cf490 'PJSIP/Provider-endpoint-00000000' hanging up.  Refs: 2
[Apr  6 20:53:31] DEBUG[-1][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Apr  6 20:53:31] DEBUG[-1][C-00000001] channel.c: Channel 0x3e193b05490 'PJSIP/${SOFTPHONE_USER}-00000001' hanging up.  Refs: 2
[Apr  6 20:53:31] DEBUG[-1][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Apr  6 20:53:31] DEBUG[-1] rtp_engine.c: Destroyed RTP instance '0x3e1462ff820'
[Apr  6 20:53:31] DEBUG[-1] rtp_engine.c: Destroyed RTP instance '0x3e0d64d2820'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Method is BYE
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Method is BYE
[Apr  6 20:53:31] DEBUG[-1] channel.c: Channel 0x3e0d64cf490 'PJSIP/Provider-endpoint-00000000' destroying
[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '${SOFTPHONE_IP}'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_resolver.c: Transport type for target '${SOFTPHONE_IP}' is 'UDP'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_resolver.c: Target '${SOFTPHONE_IP}' is an IP address, skipping resolution
[Apr  6 20:53:31] DEBUG[-1] threadpool.c: Increasing threadpool stasis/pool's size by 1
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Destroying topic. name: cache:16/channel:1586170407.0, detail: 
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Creating topic. name: channel:1586170411.2, detail: 
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Topic 'cache:16/channel:1586170407.0': 0x3e12253a3a0 destroyed
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Destroying topic. name: channel:1586170407.0, detail: 
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Topic 'channel:1586170411.2': 0x3e0dffafc20 created
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Topic 'channel:1586170407.0': 0x3e0da373920 destroyed
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Creating topic. name: cache:19/channel:1586170411.2, detail: 
[Apr  6 20:53:31] VERBOSE[-1] res_pjsip_logger.c: <--- Transmitting SIP request (426 bytes) to UDP:${SOFTPHONE_IP}:5060 --->
BYE sip:${SOFTPHONE_USER}@${SOFTPHONE_IP} SIP/2.0
Via: SIP/2.0/UDP ${ASTERISK_INT_IP}:5060;rport;branch=z9hG4bKPj87a161dc-07dd-42ec-8d5c-53c4a7579fb2
From: <sip:${HOME_PHONE}@${ASTERISK_EXT_IP}>;tag=e971c236-0ff4-4aa8-9541-f2331a066ff4
To: <sip:${SOFTPHONE_USER}@${SOFTPHONE_IP}>;tag=fjagv
Call-ID: b48f0df2-15fa-457a-8ca5-eafce2e9ab2d
CSeq: 9078 BYE
Reason: Q.850;cause=16
Max-Forwards: 70
User-Agent: Asterisk PBX 16.6.2
Content-Length:  0


[Apr  6 20:53:31] DEBUG[-1] stasis.c: Topic 'cache:19/channel:1586170411.2': 0x3e1603cb920 created
[Apr  6 20:53:31] DEBUG[-1] devicestate.c: No provider found, checking channel drivers for PJSIP - Provider-endpoint
[Apr  6 20:53:31] DEBUG[-1] devicestate.c: Changing state for PJSIP/Provider-endpoint - state 1 (Not in use)
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}(PJSIP/${SOFTPHONE_USER}-00000001)'
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Destroying topic. name: cache:19/channel:1586170411.2, detail: 
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Topic 'cache:19/channel:1586170411.2': 0x3e1603cb920 destroyed
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x3e0d64cb8a8
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Destroying topic. name: channel:1586170411.2, detail: 
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current transaction state is Calling
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Topic 'channel:1586170411.2': 0x3e0dffafc20 destroyed
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current inv state is CONFIRMED
[Apr  6 20:53:31] DEBUG[-1] channel.c: Channel 0x3e193b05490 'PJSIP/${SOFTPHONE_USER}-00000001' destroying
[Apr  6 20:53:31] VERBOSE[-1] res_pjsip_logger.c: <--- Received SIP request (452 bytes) from UDP:${PROVIDER_IP}:5060 --->
ACK sip:${ASTERISK_EXT_IP}:5060 SIP/2.0
Via: SIP/2.0/UDP ${PROVIDER_IP}:5060;branch=z9hG4bK6tqhm220b8pr47l1u-3.1
From: <sip:${HOME_PHONE}@${UPSTREAM_IP};user=phone>;tag=1760226105-1586170406639-
To: "${PROVIDER_NAME}" <sip:${SIP_PHONE}@${PROVIDER_FQDN}>;tag=fc022f98-532a-4236-b938-f906dfe82df6
Call-ID: BW10532663906042037842825@${UPSTREAM_IP}
CSeq: 663737208 ACK
Contact: <sip:${HOME_PHONE}@${PROVIDER_IP}:5060;transport=udp>
Max-Forwards: 69
Content-Length: 0


[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x3e1920d58a8 for Request msg ACK/cseq=663737208 (rdata0x3e0da8fb028)
[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002e associated with dialog dlg0x3e1920d58a8
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Destroying topic. name: cache:17/channel:1586170407.1, detail: 
[Apr  6 20:53:31] DEBUG[-1] cdr.c: CDR for PJSIP/${SOFTPHONE_USER}-00000001 is dialed and has no Party B; discarding
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Topic 'cache:17/channel:1586170407.1': 0x3e11fd8c220 destroyed
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Destroying topic. name: channel:1586170407.1, detail: 
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint()'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x3e1462ff0a8
[Apr  6 20:53:31] DEBUG[-1] stasis.c: Topic 'channel:1586170407.1': 0x3e13b3cd2a0 destroyed
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current transaction state is Terminated
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The transaction state change event is USER
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current inv state is CONNECTING
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG
[Apr  6 20:53:31] DEBUG[-1] devicestate.c: No provider found, checking channel drivers for PJSIP - ${SOFTPHONE_USER}
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint()'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:31] DEBUG[-1] devicestate.c: Changing state for PJSIP/${SOFTPHONE_USER} - state 1 (Not in use)
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current inv state is CONFIRMED
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Received request
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Method is ACK
[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '${PROVIDER_IP}'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_resolver.c: Transport type for target '${PROVIDER_IP}' is 'UDP'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_resolver.c: Target '${PROVIDER_IP}' is an IP address, skipping resolution
[Apr  6 20:53:31] VERBOSE[-1] res_pjsip_logger.c: <--- Transmitting SIP request (496 bytes) to UDP:${PROVIDER_IP}:5060 --->
BYE sip:${HOME_PHONE}@${PROVIDER_IP}:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP ${ASTERISK_EXT_IP}:5060;rport;branch=z9hG4bKPj880fc7af-11fc-4f5f-a772-7ebbe58aee79
From: "${PROVIDER_NAME}" <sip:${SIP_PHONE}@${PROVIDER_FQDN}>;tag=fc022f98-532a-4236-b938-f906dfe82df6
To: <sip:${HOME_PHONE}@${UPSTREAM_IP};user=phone>;tag=1760226105-1586170406639-
Call-ID: BW10532663906042037842825@${UPSTREAM_IP}
CSeq: 22719 BYE
Reason: Q.850;cause=16
Max-Forwards: 70
User-Agent: Asterisk PBX 16.6.2
Content-Length:  0


[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint()'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x3e0e63f98a8
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current transaction state is Calling
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current inv state is CONFIRMED
[Apr  6 20:53:31] VERBOSE[-1] res_pjsip_logger.c: <--- Received SIP response (377 bytes) from UDP:${SOFTPHONE_IP}:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP ${ASTERISK_INT_IP}:5060;received=${ASTERISK_INT_IP};rport=5060;branch=z9hG4bKPj87a161dc-07dd-42ec-8d5c-53c4a7579fb2
To: <sip:${SOFTPHONE_USER}@${SOFTPHONE_IP}>;tag=fjagv
From: <sip:${HOME_PHONE}@${ASTERISK_EXT_IP}>;tag=e971c236-0ff4-4aa8-9541-f2331a066ff4
Call-ID: b48f0df2-15fa-457a-8ca5-eafce2e9ab2d
CSeq: 9078 BYE
Server: Twinkle/1.10.1
Content-Length: 0


[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x3e0e63fb0a8 for Response msg 200/BYE/cseq=9078 (rdata0x3e0da8fb028)
[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/${SOFTPHONE_USER}-00000063 associated with dialog dlg0x3e0e63fb0a8
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}()'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current inv state is DISCONNCTD
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Received response
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Response is 200 OK
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}()'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x3e0d64cb8a8
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current transaction state is Completed
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The transaction state change event is RX_MSG
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current inv state is DISCONNCTD
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Received response
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Response is 200 OK
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: BYE received final response code 200
[Apr  6 20:53:31] VERBOSE[-1] res_pjsip_logger.c: <--- Received SIP response (407 bytes) from UDP:${PROVIDER_IP}:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP ${ASTERISK_EXT_IP}:5060;received=${ASTERISK_EXT_IP};branch=z9hG4bKPj880fc7af-11fc-4f5f-a772-7ebbe58aee79;rport=5060
From: "${PROVIDER_NAME}" <sip:${SIP_PHONE}@${PROVIDER_FQDN}>;tag=fc022f98-532a-4236-b938-f906dfe82df6
To: <sip:${HOME_PHONE}@${UPSTREAM_IP};user=phone>;tag=1760226105-1586170406639-
Call-ID: BW10532663906042037842825@${UPSTREAM_IP}
CSeq: 22719 BYE
Content-Length: 0


[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x3e1920d58a8 for Response msg 200/BYE/cseq=22719 (rdata0x3e0da8fb028)
[Apr  6 20:53:31] DEBUG[-1] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002e associated with dialog dlg0x3e1920d58a8
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint()'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: There is no transaction involved in this state change
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current inv state is DISCONNCTD
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Received response
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Response is 200 OK
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint()'
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x3e0e63f98a8
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current transaction state is Completed
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The transaction state change event is RX_MSG
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: The current inv state is DISCONNCTD
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Received response
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: Response is 200 OK
[Apr  6 20:53:31] DEBUG[-1] res_pjsip_session.c: BYE received final response code 200
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint '${SOFTPHONE_USER}()'
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x3e0d64cb8a8
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The current transaction state is Terminated
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The transaction state change event is TIMER
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The current inv state is DISCONNCTD
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: Destroying SIP session with endpoint ${SOFTPHONE_USER}
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The state change pertains to the endpoint 'Provider-endpoint()'
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x3e0e63f98a8
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The current transaction state is Terminated
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The transaction state change event is TIMER
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: The current inv state is DISCONNCTD
[Apr  6 20:53:36] DEBUG[-1] res_pjsip_session.c: Destroying SIP session with endpoint Provider-endpoint
[Apr  6 20:53:49] DEBUG[-1] res_pjsip_registrar.c: Woke up at 1586170429  Interval: 30
[Apr  6 20:53:49] DEBUG[-1] res_pjsip_registrar.c: Expiring 0 contacts
[Apr  6 20:53:51] DEBUG[-1] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr  6 20:53:51] DEBUG[-1] threadpool.c: Destroying worker thread 16
[Apr  6 20:54:12] VERBOSE[-1] asterisk.c: Remote UNIX connection
[Apr  6 20:54:12] DEBUG[-1] cdr.c: CDR Engine termination request received; waiting on messages...
[Apr  6 20:54:12] VERBOSE[-1] asterisk.c: Asterisk cleanly ending (0).
[Apr  6 20:54:12] VERBOSE[-1] asterisk.c: Executing last minute cleanups
[Apr  6 20:54:12] VERBOSE[-1] res_musiconhold.c: Destroying musiconhold processes
[Apr  6 20:54:12] DEBUG[-1] res_musiconhold.c: Destroying MOH class 'default'
[Apr  6 20:54:12] VERBOSE[-1] manager.c: Manager unregistered action DBGet
[Apr  6 20:54:12] VERBOSE[-1] manager.c: Manager unregistered action DBPut
[Apr  6 20:54:12] VERBOSE[-1] manager.c: Manager unregistered action DBDel
[Apr  6 20:54:12] VERBOSE[-1] manager.c: Manager unregistered action DBDelTree
[Apr  6 20:54:12] DEBUG[-1] asterisk.c: Asterisk ending (0).