I am trying to implement a external agteway using a Cisco 1760V with a VIC2-4FXO card and cant seem to get it functional.
Cisco config:
I added what i believed were the relevant settings in the Gateways section:
Same for inbound dialplan:
And the same for the outbound dial plan:
When i make an attempt to call out to a number i get this output in the debug logs:
From what I glean from all this, FS sets up the call session and begins to execute the call, but never actually contacts the 1760V.
When I make a call in to my 1760V via the FXO port, the output it provides shows what I would expect:
And FS displays this in its debug logs:
The way I translate all this is that FS wont call out to the 1760V because of some kind of misconfiguration, and when I call in from the PSTN, the 1760V's config is sound, but when FS recieves the session, because of a misconfiguration it either cant or wont handle the call and process it.
Any ideas folks?
Cisco config:
Code:
MTRX-WFCR-HQ-VG01#sh run
Building configuration...
Current configuration : 3408 bytes
!
version 12.4
no service pad
service timestamps debug datetime msec
service timestamps log datetime msec
service password-encryption
!
hostname MTRX-WFCR-HQ-VG01
!
boot-start-marker
boot-end-marker
!
logging buffered 20480 debugging
enable secret 5 <SNIP>
!
no aaa new-model
clock timezone GMT 0
voice-card 3
!
no ip routing
no ip cef
!
!
!
!
no ip domain lookup
ip domain name maetrix.corp
ip name-server 4.2.2.2
!
!
!
!
voice service voip
allow-connections h323 to h323
allow-connections h323 to sip
allow-connections sip to h323
allow-connections sip to sip
no supplementary-service h450.2
no supplementary-service h450.3
supplementary-service h450.12
sip
bind control source-interface FastEthernet0/0
bind media source-interface FastEthernet0/0
registrar server expires max 3600 min 3600
no call service stop
!
!
!
!
!
!
!
!
!
!
!
!
!
username admin secret 5 <SNIP>
username voiceadmin privilege 15 password 7 <SNIP>
!
!
!
!
!
!
!
interface FastEthernet0/0
description *To MTRX-WFCR-HQ-ACCESS01 Fa0/47
ip address 10.0.20.250 255.255.255.0
no ip route-cache
speed 100
!
ip default-gateway 10.0.20.254
!
!
ip http server
no ip http secure-server
!
snmp-server community <SNIP> RW
!
!
!
control-plane
!
!
!
voice-port 3/0
timeouts call-disconnect 1
timeouts wait-release 1
timing hookflash-out 50
connection plar opx 9000
caller-id enable
!
voice-port 3/1
!
voice-port 3/2
!
voice-port 3/3
!
!
!
!
!
!
dial-peer voice 100 pots
description SIP to FXO3/0
incoming called-number .T
no digit-strip
direct-inward-dial
port 3/0
forward-digits all
!
dial-peer voice 9000 voip
destination-pattern 90..
session protocol sipv2
session target ipv4:10.0.10.50
dtmf-relay rtp-nte
codec g711ulaw
no vad
!
sip-ua
registrar ipv4:10.0.10.50 expires 3600
sip-server ipv4:10.0.10.50
!
banner exec ^C
*****************************************************************************
* *
* WARNING: Unauthorized access to this system is forbidden and will be *
* prosecuted by law. By accessing this system, you agree that your *
* actions may be monitored if unauthorized usage is suspected. *
* *
*****************************************************************************
^C
banner login ^C
*****************************************************************************
* *
* WARNING - PRIVATE ELECTRONIC DEVICE - ACCESS PROHIBITED *
* *
* This device is a private network device. Access to this device is *
* *
* not authorized. Any attempt for unauthorized access will be logged *
* *
* and appropriate legal action will be taken. *
* *
*****************************************************************************
^C
!
line con 0
login local
line aux 0
line vty 0 4
login local
line vty 5 15
login local
!
endI added what i believed were the relevant settings in the Gateways section:
Same for inbound dialplan:
And the same for the outbound dial plan:
When i make an attempt to call out to a number i get this output in the debug logs:
Code:
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@10.0.10.50) State DESTROY going to sleep
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1001@10.0.10.50 Standard DESTROY
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [DEBUG] mod_sofia.c:343 sofia/internal/1001@10.0.10.50 SOFIA DESTROY
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@10.0.10.50) State DESTROY
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1001@10.0.10.50) Running State Change CS_DESTROY (Cur 0 Tot 6)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/1001@10.0.10.50 [CS_DESTROY]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [NOTICE] switch_core_session.c:1683 Session 5 (sofia/internal/1001@10.0.10.50) Ended
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [DEBUG] switch_core_session.c:1665 Session 5 (sofia/internal/1001@10.0.10.50) Locked, Waiting on external entities
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1001@10.0.10.50) State Change CS_REPORTING -> CS_DESTROY
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@10.0.10.50) State REPORTING going to sleep
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.231015 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1001@10.0.10.50 Standard REPORTING, cause: NORMAL_CLEARING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@10.0.10.50) State REPORTING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.0.10.50) Running State Change CS_REPORTING (Cur 1 Tot 6)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1001@10.0.10.50) State Change CS_HANGUP -> CS_REPORTING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@10.0.10.50) State HANGUP going to sleep
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@10.0.10.50 Standard HANGUP, cause: NORMAL_CLEARING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 480
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1001@10.0.10.50 hanging up, cause: NORMAL_CLEARING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@10.0.10.50) State HANGUP
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1001@10.0.10.50) Callstate Change RINGING -> HANGUP
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.0.10.50) Running State Change CS_HANGUP (Cur 1 Tot 6)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@10.0.10.50) State EXECUTE going to sleep
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/1001@10.0.10.50 [CS_EXECUTE] [NORMAL_CLEARING]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [NOTICE] switch_core_state_machine.c:385 sofia/internal/1001@10.0.10.50 has executed the last dialplan instruction, hanging up.
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [INFO] mod_dptools.c:3436 Originate Failed. Cause: GATEWAY_DOWN
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 609 [GATEWAY_DOWN]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [sofia] cause: [GATEWAY_DOWN]
306af846-55a9-11e9-b02c-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:751 (N/A) State DESTROY going to sleep
306af846-55a9-11e9-b02c-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_sofia.c:343 N/A SOFIA DESTROY
306af846-55a9-11e9-b02c-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:751 (N/A) State DESTROY
306af846-55a9-11e9-b02c-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:741 () Running State Change CS_DESTROY (Cur 1 Tot 6)
306af846-55a9-11e9-b02c-859102276f44 2019-04-02 17:41:16.153962 [NOTICE] mod_sofia.c:4918 Close Channel N/A [CS_NEW]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [ERR] mod_sofia.c:4509 Gateway 68335a25-07d8-4239-bb17-bbb980f48311 is down!
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_channel.c:1250 sofia/internal/1001@10.0.10.50 EXPORTING[export_vars] [call_direction]=[outbound] to event
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_channel.c:1250 sofia/internal/1001@10.0.10.50 EXPORTING[export_vars] [origination_callee_id_name]=[915416599905] to event
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_channel.c:1250 sofia/internal/1001@10.0.10.50 EXPORTING[export_vars] [call_direction]=[outbound] to event
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_channel.c:1250 sofia/internal/1001@10.0.10.50 EXPORTING[export_vars] [domain_name]=[10.0.10.50] to event
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 bridge(sofia/gateway/68335a25-07d8-4239-bb17-bbb980f48311/15416599905)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [outbound_prefix]=[9]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(outbound_prefix=9)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [continue_on_fail]=[true]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(continue_on_fail=true)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [callee_id_number]=[15416599905]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(callee_id_number=15416599905)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [ignore_display_updates]=[true]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(ignore_display_updates=true)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [inherit_codec]=[true]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(inherit_codec=true)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [effective_caller_id_number]=[UNDEF]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(effective_caller_id_number=)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [effective_caller_id_name]=[UNDEF]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(effective_caller_id_name=)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [hangup_after_bridge]=[true]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(hangup_after_bridge=true)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1693 UNSET [call_timeout]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 unset(call_timeout)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[outbound]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 export(call_direction=outbound)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [sip_h_X-accountcode]=[UNDEF]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(sip_h_X-accountcode=)
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 hash(insert/10.0.10.50-last_dial/1001/915416599905)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [RFC2822_DATE]=[Tue, 02 Apr 2019 17:41:16 -0700]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(RFC2822_DATE=Tue, 02 Apr 2019 17:41:16 -0700)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[915416599905]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 export(origination_callee_id_name=915416599905)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[local]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 export(call_direction=local)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1001@10.0.10.50 Standard EXECUTE
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_sofia.c:198 sofia/internal/1001@10.0.10.50 SOFIA EXECUTE
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@10.0.10.50) State EXECUTE
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.0.10.50) Running State Change CS_EXECUTE (Cur 1 Tot 5)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@10.0.10.50) State ROUTING going to sleep
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1001@10.0.10.50) State Change CS_ROUTING -> CS_EXECUTE
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action bridge(sofia/gateway/68335a25-07d8-4239-bb17-bbb980f48311/15416599905)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(outbound_prefix=9)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(continue_on_fail=true)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(callee_id_number=15416599905)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(ignore_display_updates=true)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(inherit_codec=true)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(effective_caller_id_number=${outbound_caller_id_number})
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(effective_caller_id_name=${outbound_caller_id_name})
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(hangup_after_bridge=true)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action unset(call_timeout)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action export(call_direction=outbound)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(sip_h_X-accountcode=${accountcode})
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [MTRX-WFCR-120PRK-VG01.9.11d] destination_number(915416599905) =~ /^9(\d{11})$/ break=on-false
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [MTRX-WFCR-120PRK-VG01.9.11d] ${user_exists}(false) =~ /false/ break=on-false
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 parsing [10.0.10.50->MTRX-WFCR-120PRK-VG01.9.11d] continue=false
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [outbound_caller_id_number]=[UNDEF]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(outbound_caller_id_number=)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [outbound_caller_id_name]=[UNDEF]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(outbound_caller_id_name=)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [emergency_caller_id_number]=[UNDEF]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(emergency_caller_id_number=)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [emergency_caller_id_name]=[UNDEF]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(emergency_caller_id_name=)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 parsing [10.0.10.50->default_caller_id] continue=true
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [speed_dial] destination_number(915416599905) =~ /^\*0(.*)$/ break=on-false
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 parsing [10.0.10.50->speed_dial] continue=false
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [redial] () =~ // break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [redial] destination_number(915416599905) =~ /^(redial|\*870)$/ break=on-true
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 parsing [10.0.10.50->redial] continue=true
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.153962 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [from_user_record]=[UNDEF]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(from_user_record=)
2019-04-02 17:41:16.153962 [ERR] switch_cpp.cpp:1365 [cache] can not write file `/var/cache/fusionpbx/directory.1001@10.0.10.50.306a1de0-55a9-11e9-b015-859102276f44.tmp`: /var/cache/fusionpbx/directory.1001@10.0.10.50.306a1de0-55a9-11e9-b015-859102276f44.tmp: No such file or directory
2019-04-02 17:41:16.153962 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fcd94097420 released.
2019-04-02 17:41:16.112373 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fcd94097420 Connected.
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [from_user_exists]=[true]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(from_user_exists=true)
2019-04-02 17:41:16.112373 [ERR] switch_cpp.cpp:1365 [cache] can not write file `/var/cache/fusionpbx/directory.1001@10.0.10.50.30684542-55a9-11e9-b013-859102276f44.tmp`: /var/cache/fusionpbx/directory.1001@10.0.10.50.30684542-55a9-11e9-b013-859102276f44.tmp: No such file or directory
2019-04-02 17:41:16.112373 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fcd94097420 released.
2019-04-02 17:41:16.112373 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fcd94097420 Connected.
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [user_record] () =~ // break=on-false
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 parsing [10.0.10.50->user_record] continue=true
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action export(origination_callee_id_name=${destination_number})
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [variables] () =~ // break=on-false
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 parsing [10.0.10.50->variables] continue=true
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 ANTI-Action export(call_direction=local)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 parsing [10.0.10.50->call-direction] continue=true
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [caller_id_number]=[1001]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(caller_id_number=1001)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(caller_id_number=${caller_id_number}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [caller_id_name]=[1001]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(caller_id_name=1001)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(caller_id_name=${caller_id_name}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [caller_destination]=[915416599905]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(caller_destination=915416599905)
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(caller_destination=${destination_number}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 parsing [10.0.10.50->caller-details] continue=true
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@10.0.10.50 [user_exists]=[false]
305b71e6-55a9-11e9-b009-859102276f44 EXECUTE sofia/internal/1001@10.0.10.50 set(user_exists=false)
2019-04-02 17:41:16.112373 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fcd94097420 released.
2019-04-02 17:41:16.112373 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fcd94097420 Connected.
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 Regex (PASS) [user_exists] () =~ // break=on-false
305b71e6-55a9-11e9-b009-859102276f44 Dialplan: sofia/internal/1001@10.0.10.50 parsing [10.0.10.50->user_exists] continue=true
2019-04-02 17:41:16.112373 [ERR] switch_cpp.cpp:1365 [cache] can not write file `/var/cache/fusionpbx/dialplan.10.0.10.50.30652eca-55a9-11e9-b00d-859102276f44.tmp`: /var/cache/fusionpbx/dialplan.10.0.10.50.30652eca-55a9-11e9-b00d-859102276f44.tmp: No such file or directory
2019-04-02 17:41:16.112373 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fcd94097420 released.
2019-04-02 17:41:16.112373 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fcd94097420 Connected.
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [INFO] mod_dialplan_xml.c:637 Processing SIP USER <1001>->915416599905 in context 10.0.10.50
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1001@10.0.10.50 Standard ROUTING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] mod_sofia.c:143 sofia/internal/1001@10.0.10.50 SOFIA ROUTING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@10.0.10.50) State ROUTING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_channel.c:2249 (sofia/internal/1001@10.0.10.50) Callstate Change DOWN -> RINGING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.0.10.50) Running State Change CS_ROUTING (Cur 1 Tot 5)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@10.0.10.50) State INIT going to sleep
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@10.0.10.50) State Change CS_INIT -> CS_ROUTING
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@10.0.10.50 Standard INIT
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] mod_sofia.c:90 sofia/internal/1001@10.0.10.50 SOFIA INIT
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@10.0.10.50) State INIT
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.0.10.50) Running State Change CS_INIT (Cur 1 Tot 5)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] sofia.c:7507 (sofia/internal/1001@10.0.10.50) State Change CS_NEW -> CS_INIT
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:5001 No matches with inherit_codec, fallback to ignoring PT
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4993 No matches with FTMP, fallback to ignoring FMTP
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4767 sofia/internal/1001@10.0.10.50 Set 2833 dtmf send payload to 127 recv payload to 127
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 127@8000
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@10.0.10.50 Original read codec set to G722:9
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/1001@10.0.10.50 G722/8000 20 ms 160 samples 64000 bits 1 channels
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 127@8000
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:107:16000:20:32000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:115:32000:20:48000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:107:16000:20:32000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:115:32000:20:48000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:107:16000:20:32000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:115:32000:20:48000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:32000:1]/[PCMA:8:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:32000:1]/[PCMU:0:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:32000:1]/[G722:9:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G7221:107:16000:20:32000:1] ++++ is saved as a match
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:32000:1]/[G7221:107:16000:20:32000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G7221:102:16000:20:32000:1]/[G7221:115:32000:20:48000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G7221:107:16000:20:32000:1]
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G7221:115:32000:20:48000:1]
305b71e6-55a9-11e9-b009-859102276f44
305b71e6-55a9-11e9-b009-859102276f44 a=fmtp:34 CIF=1;QCIF=1;SQCIF=1
305b71e6-55a9-11e9-b009-859102276f44 a=rtpmap:34 H263/90000
305b71e6-55a9-11e9-b009-859102276f44 a=fmtp:109 profile-level-id=42800d
305b71e6-55a9-11e9-b009-859102276f44 a=rtpmap:109 H264/90000
305b71e6-55a9-11e9-b009-859102276f44 m=video 2232 RTP/AVP 109 34
305b71e6-55a9-11e9-b009-859102276f44 a=rtpmap:127 telephone-event/8000
305b71e6-55a9-11e9-b009-859102276f44 a=fmtp:18 annexb=no
305b71e6-55a9-11e9-b009-859102276f44 a=rtpmap:18 G729/8000
305b71e6-55a9-11e9-b009-859102276f44 a=rtpmap:8 PCMA/8000
305b71e6-55a9-11e9-b009-859102276f44 a=rtpmap:0 PCMU/8000
305b71e6-55a9-11e9-b009-859102276f44 a=fmtp:102 bitrate=32000
305b71e6-55a9-11e9-b009-859102276f44 a=rtpmap:102 G7221/16000
305b71e6-55a9-11e9-b009-859102276f44 a=rtpmap:9 G722/8000
305b71e6-55a9-11e9-b009-859102276f44 m=audio 2230 RTP/AVP 9 102 0 8 18 127
305b71e6-55a9-11e9-b009-859102276f44 a=sendrecv
305b71e6-55a9-11e9-b009-859102276f44 t=0 0
305b71e6-55a9-11e9-b009-859102276f44 b=AS:512
305b71e6-55a9-11e9-b009-859102276f44 c=IN IP4 10.0.20.52
305b71e6-55a9-11e9-b009-859102276f44 s=Polycom IP Phone
305b71e6-55a9-11e9-b009-859102276f44 o=- 1554252076 1554252076 IN IP4 10.0.20.52
305b71e6-55a9-11e9-b009-859102276f44 v=0
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] sofia.c:7094 Remote SDP:
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.112373 [DEBUG] sofia.c:7084 Channel sofia/internal/1001@10.0.10.50 entering state [received][100]
2019-04-02 17:41:16.112373 [ERR] switch_cpp.cpp:1365 [cache] can not write file `/var/cache/fusionpbx/directory.1001@10.0.10.50.3063dbc4-55a9-11e9-b00b-859102276f44.tmp`: /var/cache/fusionpbx/directory.1001@10.0.10.50.3063dbc4-55a9-11e9-b00b-859102276f44.tmp: No such file or directory
2019-04-02 17:41:16.112373 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fcd94097420 released.
2019-04-02 17:41:16.112373 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fcd94097420 Connected.
2019-04-02 17:41:16.091166 [DEBUG] sofia.c:10044 IP 10.0.20.52 Rejected by acl "domains". Falling back to Digest auth.
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.091166 [DEBUG] sofia.c:9873 sofia/internal/1001@10.0.10.50 receiving invite from 10.0.20.52:5060 version: 1.6.20 64bit
2019-04-02 17:41:16.091166 [DEBUG] sofia.c:2442 Re-attaching to session 305b71e6-55a9-11e9-b009-859102276f44
2019-04-02 17:41:16.051155 [DEBUG] sofia.c:2334 detaching session 305b71e6-55a9-11e9-b009-859102276f44
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.051155 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1001@10.0.10.50) State NEW
2019-04-02 17:41:16.051155 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [915416599905@10.0.10.50] from ip 10.0.20.52
2019-04-02 17:41:16.051155 [DEBUG] sofia.c:10044 IP 10.0.20.52 Rejected by acl "domains". Falling back to Digest auth.
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.051155 [DEBUG] sofia.c:9873 sofia/internal/1001@10.0.10.50 receiving invite from 10.0.20.52:5060 version: 1.6.20 64bit
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.051155 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.0.10.50) Running State Change CS_NEW (Cur 1 Tot 5)
305b71e6-55a9-11e9-b009-859102276f44 2019-04-02 17:41:16.051155 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@10.0.10.50 [305b71e6-55a9-11e9-b009-859102276f44]From what I glean from all this, FS sets up the call session and begins to execute the call, but never actually contacts the 1760V.
When I make a call in to my 1760V via the FXO port, the output it provides shows what I would expect:
Code:
*Jun 1 06:39:14.492: //128/000000000000/SIP/State/sipSPIChangeState: 0x843AD2BC : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Jun 1 06:39:14.496: //128/000000000000/SIP/Info/ccsip_call_setup_request:
This is a TDM-IP call: callID= 128, peer_callID = 127
*Jun 1 06:39:14.496: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP
*Jun 1 06:39:14.496: //128/1F983C1E81A1/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 80 to table
*Jun 1 06:39:14.500: //128/1F983C1E81A1/SIP/Info/act_idle_continue_call_setup:
*Jun 1 06:39:14.500: //128/1F983C1E81A1/SIP/Info/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec bytes: 0
*Jun 1 06:39:14.500: //128/1F983C1E81A1/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
*Jun 1 06:39:14.500: //128/1F983C1E81A1/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec
*Jun 1 06:39:14.500: //128/1F983C1E81A1/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp:
callid 128, channels 0x0 caps 0x0
*Jun 1 06:39:14.500: //128/1F983C1E81A1/SIP/Info/sipSPIValidateGtd: Signal Forward disabled
*Jun 1 06:39:14.500: //128/1F983C1E81A1/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0
*Jun 1 06:39:14.504: //128/1F983C1E81A1/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
*Jun 1 06:39:14.504: //128/1F983C1E81A1/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x843AD2BC key=1F9D1FC0-746111D6-81A4F4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:14.504: //128/1F983C1E81A1/SIP/Info/sipSPIUsetBillingProfile: sipCallId for billing records = 1F9D1FC0-746111D6-81A4F4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:14.504: //128/1F983C1E81A1/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.0.20.250
*Jun 1 06:39:14.504: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 18932 for stream 1
*Jun 1 06:39:14.504: //128/1F983C1E81A1/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101
*Jun 1 06:39:14.508: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20
*Jun 1 06:39:14.508: //128/1F983C1E81A1/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed
*Jun 1 06:39:14.508: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.0.10.50,Port 5060, Transport 1, SentBy Port 5060
*Jun 1 06:39:14.508: //128/1F983C1E81A1/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off
*Jun 1 06:39:14.516: //128/1F983C1E81A1/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer
*Jun 1 06:39:14.516: //128/1F983C1E81A1/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
*Jun 1 06:39:14.516: //128/1F983C1E81A1/SIP/Transport/sipSPITransportSendMessage: msg=0x845D3B00, addr=10.0.10.50, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x80B17F40
*Jun 1 06:39:14.516: //128/1F983C1E81A1/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jun 1 06:39:14.516: //128/1F983C1E81A1/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jun 1 06:39:14.516: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x845D3DD0,addr=10.0.10.50
*Jun 1 06:39:14.516: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnHolder: Created new holder=0x845D3DD0, addr=10.0.10.50
*Jun 1 06:39:14.516: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostRequestConnection: Posting UDP conn create request for addr=10.0.10.50, port=5060, context=0x83FB626C
*Jun 1 06:39:14.516: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer: Wait timer set for connection=0x83FB6CD0,addr=10.0.10.50, port=5060
*Jun 1 06:39:14.520: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnInstance: Created new initiated conn=0x83FB6CD0, connid=-1, addr=10.0.10.50, port=5060, transport=udp
*Jun 1 06:39:14.520: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering ccb=0x843AD2BC with connection=0x83FB6CD0
*Jun 1 06:39:14.520: //128/1F983C1E81A1/SIP/Transport/sipSPITransportSendMessage: Deferred sending msg=0x845D3B00
*Jun 1 06:39:14.520: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWConnectionCreated: context=0x83FB626C
*Jun 1 06:39:14.524: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessConnCreated: gConnTab=0x83FB626C, addr=10.0.10.50, port=5060, connid=1, transport=udp
*Jun 1 06:39:14.524: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportStopConnWaitTimer: Wait timer stopped for connection=0x83FB6CD0,addr=10.0.10.50, port=5060
*Jun 1 06:39:14.524: //128/1F983C1E81A1/SIP/Transport/sipTransportPostInternalMsg: Posting Internal Msg type=0
*Jun 1 06:39:14.524: //128/1F983C1E81A1/SIP/Info/ccsip_lock_ccb: CCB locked; reference count=1
*Jun 1 06:39:14.524: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessInternalMsg: context=0x843AD2BC
*Jun 1 06:39:14.524: //128/1F983C1E81A1/SIP/Info/ccsip_unlock_ccb: CCB unlocked; reference count=0
*Jun 1 06:39:14.524: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x845D3B00, addr=10.0.10.50, port=5060, connId=1 for UDP
*Jun 1 06:39:14.524: //128/1F983C1E81A1/SIP/Info/sentInviteRequest: Sent Invite in state STATE_IDLE
*Jun 1 06:39:14.524: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteRequest: Transaction active. Facilities will be queued.
*Jun 1 06:39:14.524: //128/1F983C1E81A1/SIP/State/sipSPIChangeState: 0x843AD2BC : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_SENT_INVITE, SUBSTATE_NONE)
*Jun 1 06:39:14.528: //128/1F983C1E81A1/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions
*Jun 1 06:39:14.528: //128/1F983C1E81A1/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 128) to the VOIP RTP library
*Jun 1 06:39:14.528: //128/1F983C1E81A1/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.0.20.250
*Jun 1 06:39:14.528: //128/1F983C1E81A1/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1
*Jun 1 06:39:14.528: //128/1F983C1E81A1/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info
laddr = 10.0.20.250, lport = 18932, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE
src_callid = 128, dest_callid = -1, stream type = voice+dtmf, stream direction = RECVONLY
media_ip_addr = 0.0.0.0
*Jun 1 06:39:14.528: //128/1F983C1E81A1/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one
*Jun 1 06:39:14.532: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
INVITE sip:9000@10.0.10.50:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK84B39
From: "U.S. CELLULAR" <sip:5416599905@10.0.10.50>;tag=36911B99-15B6
To: <sip:9000@10.0.10.50>
Date: Sat, 01 Jun 2002 06:39:14 GMT
Call-ID: 1F9D1FC0-746111D6-81A4F4AD-2C1F9709@10.0.20.250
Supported: 100rel,timer,replaces
Min-SE: 1800
Cisco-Guid: 530070558-1952518614-2174874797-740267785
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
CSeq: 101 INVITE
Max-Forwards: 70
Remote-Party-ID: "U.S. CELLULAR" <sip:5416599905@10.0.20.250>;party=calling;screen=no;privacy=off
Timestamp: 1022913554
Contact: <sip:5416599905@10.0.20.250:5060>
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 243
v=0
o=CiscoSystemsSIP-GW-UserAgent 862 6618 IN IP4 10.0.20.250
s=SIP Call
c=IN IP4 10.0.20.250
t=0 0
m=audio 18932 RTP/AVP 0 101
c=IN IP4 10.0.20.250
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
*Jun 1 06:39:14.536: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.0.10.50:5060
*Jun 1 06:39:14.540: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.0.10.50:5060
*Jun 1 06:39:14.545: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jun 1 06:39:14.545: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK84B39
From: "U.S. CELLULAR" <sip:5416599905@10.0.10.50>;tag=36911B99-15B6
To: <sip:9000@10.0.10.50>
Call-ID: 1F9D1FC0-746111D6-81A4F4AD-2C1F9709@10.0.20.250
CSeq: 101 INVITE
Timestamp: 1022913554 0.000087
User-Agent: FreeSWITCH
Content-Length: 0
*Jun 1 06:39:14.545: //128/1F983C1E81A1/SIP/State/sipSPIChangeState: 0x843AD2BC : State change from (STATE_SENT_INVITE, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)
*Jun 1 06:39:14.549: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jun 1 06:39:14.549: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK84B39
From: "U.S. CELLULAR" <sip:5416599905@10.0.10.50>;tag=36911B99-15B6
To: <sip:9000@10.0.10.50>;tag=D8SSmFacc06Da
Call-ID: 1F9D1FC0-746111D6-81A4F4AD-2C1F9709@10.0.20.250
CSeq: 101 INVITE
User-Agent: FreeSWITCH
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="10.0.10.50", nonce="76d5ce7c-55aa-11e9-b052-859102276f44", algorithm=MD5, qop="auth"
Content-Length: 0
*Jun 1 06:39:14.553: //128/1F983C1E81A1/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer
*Jun 1 06:39:14.553: //128/1F983C1E81A1/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
*Jun 1 06:39:14.553: //128/1F983C1E81A1/SIP/Transport/sipSPITransportSendMessage: msg=0x845D33B0, addr=10.0.10.50, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000
*Jun 1 06:39:14.553: //128/1F983C1E81A1/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jun 1 06:39:14.553: //128/1F983C1E81A1/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jun 1 06:39:14.557: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x845D33B0, addr=10.0.10.50, port=5060, connId=0 for UDP
*Jun 1 06:39:14.557: //128/1F983C1E81A1/SIP/Info/act_recdproc_new_message_response: Received a 4/5/6xx message with StatusCode: 407
*Jun 1 06:39:14.557: //128/1F983C1E81A1/SIP/Error/sipSPIHandleAuthChallenge: Error getting credentials
*Jun 1 06:39:14.557: //128/1F983C1E81A1/SIP/Error/act_recdproc_new_message_response: Error handling AuthenticationChallenge
*Jun 1 06:39:14.557: //128/1F983C1E81A1/SIP/State/sipSPIChangeState: 0x843AD2BC : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Jun 1 06:39:14.557: //128/1F983C1E81A1/SIP/Info/ccsip_set_cc_cause_for_spi_err: Categorized cause:47, category:181
*Jun 1 06:39:14.557: //128/1F983C1E81A1/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(47) for outgoing call
*Jun 1 06:39:14.557: //128/1F983C1E81A1/SIP/State/sipSPIChangeState: 0x843AD2BC : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Jun 1 06:39:14.557: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[128], src[6]
*Jun 1 06:39:14.561: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
ACK sip:9000@10.0.10.50:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK84B39
From: "U.S. CELLULAR" <sip:5416599905@10.0.10.50>;tag=36911B99-15B6
To: <sip:9000@10.0.10.50>;tag=D8SSmFacc06Da
Date: Sat, 01 Jun 2002 06:39:14 GMT
Call-ID: 1F9D1FC0-746111D6-81A4F4AD-2C1F9709@10.0.20.250
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0
*Jun 1 06:39:14.565: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
*Jun 1 06:39:14.565: //128/1F983C1E81A1/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:91547950 ConnTime 0
*Jun 1 06:39:14.565: //128/1F983C1E81A1/SIP/State/sipSPIChangeState: 0x843AD2BC : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
*Jun 1 06:39:14.569: //128/1F983C1E81A1/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x843AD2BC
State of The Call : STATE_DEAD
TCP Sockets Used : NO
Calling Number : 5416599905
Called Number : 9000
Source IP Address (Sig ): 10.0.20.250
Destn SIP Req Addr:Port : 10.0.10.50:5060
Destn SIP Resp Addr:Port : 10.0.10.50:5060
Destination Name : 10.0.10.50
*Jun 1 06:39:14.569: //128/1F983C1E81A1/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : No Codec
Negotiated Codec Bytes : 0
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0
Source IP Address (Media): 10.0.20.250
Source IP Port (Media): 18932
Destn IP Address (Media): 0.0.0.0
Destn IP Port (Media): 0
Orig Destn IP Address:Port (Media): 0.0.0.0:0
*Jun 1 06:39:14.569: //128/1F983C1E81A1/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 47
Disconnect Cause (SIP) : 407
*Jun 1 06:39:14.569: //128/1F983C1E81A1/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 80
*Jun 1 06:39:24.641: //130/000000000000/SIP/State/sipSPIChangeState: 0x843A6038 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Jun 1 06:39:24.641: //130/000000000000/SIP/Info/ccsip_call_setup_request:
This is a TDM-IP call: callID= 130, peer_callID = 129
*Jun 1 06:39:24.641: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP
*Jun 1 06:39:24.645: //130/25A5671081A5/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 82 to table
*Jun 1 06:39:24.645: //130/25A5671081A5/SIP/Info/act_idle_continue_call_setup:
*Jun 1 06:39:24.645: //130/25A5671081A5/SIP/Info/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec bytes: 0
*Jun 1 06:39:24.645: //130/25A5671081A5/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
*Jun 1 06:39:24.645: //130/25A5671081A5/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec
*Jun 1 06:39:24.649: //130/25A5671081A5/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp:
callid 130, channels 0x0 caps 0x0
*Jun 1 06:39:24.649: //130/25A5671081A5/SIP/Info/sipSPIValidateGtd: Signal Forward disabled
*Jun 1 06:39:24.649: //130/25A5671081A5/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0
*Jun 1 06:39:24.649: //130/25A5671081A5/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
*Jun 1 06:39:24.649: //130/25A5671081A5/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x843A6038 key=25A91262-746111D6-81A8F4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:24.649: //130/25A5671081A5/SIP/Info/sipSPIUsetBillingProfile: sipCallId for billing records = 25A91262-746111D6-81A8F4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:24.653: //130/25A5671081A5/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.0.20.250
*Jun 1 06:39:24.653: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 16512 for stream 1
*Jun 1 06:39:24.653: //130/25A5671081A5/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101
*Jun 1 06:39:24.653: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20
*Jun 1 06:39:24.653: //130/25A5671081A5/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed
*Jun 1 06:39:24.657: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.0.10.50,Port 5060, Transport 1, SentBy Port 5060
*Jun 1 06:39:24.661: //130/25A5671081A5/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer
*Jun 1 06:39:24.661: //130/25A5671081A5/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
*Jun 1 06:39:24.661: //130/25A5671081A5/SIP/Transport/sipSPITransportSendMessage: msg=0x845D33B0, addr=10.0.10.50, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x80B17F40
*Jun 1 06:39:24.661: //130/25A5671081A5/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jun 1 06:39:24.661: //130/25A5671081A5/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jun 1 06:39:24.661: //130/25A5671081A5/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x845D33B0
*Jun 1 06:39:24.665: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x845D33B0, addr=10.0.10.50, port=5060, connId=1 for UDP
*Jun 1 06:39:24.665: //130/25A5671081A5/SIP/Info/sentInviteRequest: Sent Invite in state STATE_IDLE
*Jun 1 06:39:24.665: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteRequest: Transaction active. Facilities will be queued.
*Jun 1 06:39:24.665: //130/25A5671081A5/SIP/State/sipSPIChangeState: 0x843A6038 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_SENT_INVITE, SUBSTATE_NONE)
*Jun 1 06:39:24.665: //130/25A5671081A5/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions
*Jun 1 06:39:24.665: //130/25A5671081A5/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 130) to the VOIP RTP library
*Jun 1 06:39:24.665: //130/25A5671081A5/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.0.20.250
*Jun 1 06:39:24.665: //130/25A5671081A5/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1
*Jun 1 06:39:24.665: //130/25A5671081A5/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info
laddr = 10.0.20.250, lport = 16512, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE
src_callid = 130, dest_callid = -1, stream type = voice+dtmf, stream direction = RECVONLY
media_ip_addr = 0.0.0.0
*Jun 1 06:39:24.669: //130/25A5671081A5/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one
*Jun 1 06:39:24.673: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
INVITE sip:9000@10.0.10.50:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK8521D0
From: <sip:10.0.10.50>;tag=3691433E-1867
To: <sip:9000@10.0.10.50>
Date: Sat, 01 Jun 2002 06:39:24 GMT
Call-ID: 25A91262-746111D6-81A8F4AD-2C1F9709@10.0.20.250
Supported: 100rel,timer,replaces
Min-SE: 1800
Cisco-Guid: 631596816-1952518614-2175136941-740267785
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
CSeq: 101 INVITE
Max-Forwards: 70
Timestamp: 1022913564
Contact: <sip:10.0.20.250:5060>
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 244
v=0
o=CiscoSystemsSIP-GW-UserAgent 8161 1881 IN IP4 10.0.20.250
s=SIP Call
c=IN IP4 10.0.20.250
t=0 0
m=audio 16512 RTP/AVP 0 101
c=IN IP4 10.0.20.250
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
*Jun 1 06:39:24.677: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.0.10.50:5060
*Jun 1 06:39:24.681: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.0.10.50:5060
*Jun 1 06:39:24.681: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jun 1 06:39:24.681: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK8521D0
From: <sip:10.0.10.50>;tag=3691433E-1867
To: <sip:9000@10.0.10.50>
Call-ID: 25A91262-746111D6-81A8F4AD-2C1F9709@10.0.20.250
CSeq: 101 INVITE
Timestamp: 1022913564 0.000096
User-Agent: FreeSWITCH
Content-Length: 0
*Jun 1 06:39:24.685: //130/25A5671081A5/SIP/State/sipSPIChangeState: 0x843A6038 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)
*Jun 1 06:39:24.685: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jun 1 06:39:24.685: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK8521D0
From: <sip:10.0.10.50>;tag=3691433E-1867
To: <sip:9000@10.0.10.50>;tag=eHKjpaUF98v0N
Call-ID: 25A91262-746111D6-81A8F4AD-2C1F9709@10.0.20.250
CSeq: 101 INVITE
User-Agent: FreeSWITCH
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="10.0.10.50", nonce="7ce0ed1a-55aa-11e9-b054-859102276f44", algorithm=MD5, qop="auth"
Content-Length: 0
*Jun 1 06:39:24.689: //130/25A5671081A5/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer
*Jun 1 06:39:24.689: //130/25A5671081A5/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
*Jun 1 06:39:24.689: //130/25A5671081A5/SIP/Transport/sipSPITransportSendMessage: msg=0x845D3B00, addr=10.0.10.50, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000
*Jun 1 06:39:24.693: //130/25A5671081A5/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jun 1 06:39:24.693: //130/25A5671081A5/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jun 1 06:39:24.693: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x845D3B00, addr=10.0.10.50, port=5060, connId=0 for UDP
*Jun 1 06:39:24.693: //130/25A5671081A5/SIP/Info/act_recdproc_new_message_response: Received a 4/5/6xx message with StatusCode: 407
*Jun 1 06:39:24.693: //130/25A5671081A5/SIP/Error/sipSPIHandleAuthChallenge: Error getting credentials
*Jun 1 06:39:24.693: //130/25A5671081A5/SIP/Error/act_recdproc_new_message_response: Error handling AuthenticationChallenge
*Jun 1 06:39:24.693: //130/25A5671081A5/SIP/State/sipSPIChangeState: 0x843A6038 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Jun 1 06:39:24.693: //130/25A5671081A5/SIP/Info/ccsip_set_cc_cause_for_spi_err: Categorized cause:47, category:181
*Jun 1 06:39:24.693: //130/25A5671081A5/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(47) for outgoing call
*Jun 1 06:39:24.697: //130/25A5671081A5/SIP/State/sipSPIChangeState: 0x843A6038 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Jun 1 06:39:24.697: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[130], src[6]
*Jun 1 06:39:24.701: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
ACK sip:9000@10.0.10.50:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK8521D0
From: <sip:10.0.10.50>;tag=3691433E-1867
To: <sip:9000@10.0.10.50>;tag=eHKjpaUF98v0N
Date: Sat, 01 Jun 2002 06:39:24 GMT
Call-ID: 25A91262-746111D6-81A8F4AD-2C1F9709@10.0.20.250
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0
*Jun 1 06:39:24.701: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
*Jun 1 06:39:24.705: //130/25A5671081A5/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:91548964 ConnTime 0
*Jun 1 06:39:24.705: //130/25A5671081A5/SIP/State/sipSPIChangeState: 0x843A6038 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
*Jun 1 06:39:24.705: //130/25A5671081A5/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x843A6038
State of The Call : STATE_DEAD
TCP Sockets Used : NO
Calling Number :
Called Number : 9000
Source IP Address (Sig ): 10.0.20.250
Destn SIP Req Addr:Port : 10.0.10.50:5060
Destn SIP Resp Addr:Port : 10.0.10.50:5060
Destination Name : 10.0.10.50
*Jun 1 06:39:24.709: //130/25A5671081A5/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : No Codec
Negotiated Codec Bytes : 0
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0
Source IP Address (Media): 10.0.20.250
Source IP Port (Media): 16512
Destn IP Address (Media): 0.0.0.0
Destn IP Port (Media): 0
Orig Destn IP Address:Port (Media): 0.0.0.0:0
*Jun 1 06:39:24.709: //130/25A5671081A5/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 47
Disconnect Cause (SIP) : 407
*Jun 1 06:39:24.709: //130/25A5671081A5/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 82
*Jun 1 06:39:36.697: //132/000000000000/SIP/State/sipSPIChangeState: 0x843AAC90 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Jun 1 06:39:36.701: //132/000000000000/SIP/Info/ccsip_call_setup_request:
This is a TDM-IP call: callID= 132, peer_callID = 131
*Jun 1 06:39:36.701: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP
*Jun 1 06:39:36.701: //132/2CD593A881A9/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 84 to table
*Jun 1 06:39:36.705: //132/2CD593A881A9/SIP/Info/act_idle_continue_call_setup:
*Jun 1 06:39:36.705: //132/2CD593A881A9/SIP/Info/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec bytes: 0
*Jun 1 06:39:36.705: //132/2CD593A881A9/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
*Jun 1 06:39:36.705: //132/2CD593A881A9/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec
*Jun 1 06:39:36.705: //132/2CD593A881A9/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp:
callid 132, channels 0x0 caps 0x0
*Jun 1 06:39:36.705: //132/2CD593A881A9/SIP/Info/sipSPIValidateGtd: Signal Forward disabled
*Jun 1 06:39:36.705: //132/2CD593A881A9/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0
*Jun 1 06:39:36.709: //132/2CD593A881A9/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
*Jun 1 06:39:36.709: //132/2CD593A881A9/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x843AAC90 key=2CD93EFA-746111D6-81ACF4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:36.709: //132/2CD593A881A9/SIP/Info/sipSPIUsetBillingProfile: sipCallId for billing records = 2CD93EFA-746111D6-81ACF4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:36.709: //132/2CD593A881A9/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.0.20.250
*Jun 1 06:39:36.709: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 19248 for stream 1
*Jun 1 06:39:36.713: //132/2CD593A881A9/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101
*Jun 1 06:39:36.713: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20
*Jun 1 06:39:36.713: //132/2CD593A881A9/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed
*Jun 1 06:39:36.713: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.0.10.50,Port 5060, Transport 1, SentBy Port 5060
*Jun 1 06:39:36.717: //132/2CD593A881A9/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer
*Jun 1 06:39:36.717: //132/2CD593A881A9/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
*Jun 1 06:39:36.721: //132/2CD593A881A9/SIP/Transport/sipSPITransportSendMessage: msg=0x845D3B00, addr=10.0.10.50, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x80B17F40
*Jun 1 06:39:36.721: //132/2CD593A881A9/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jun 1 06:39:36.721: //132/2CD593A881A9/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jun 1 06:39:36.721: //132/2CD593A881A9/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x845D3B00
*Jun 1 06:39:36.721: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x845D3B00, addr=10.0.10.50, port=5060, connId=1 for UDP
*Jun 1 06:39:36.721: //132/2CD593A881A9/SIP/Info/sentInviteRequest: Sent Invite in state STATE_IDLE
*Jun 1 06:39:36.721: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteRequest: Transaction active. Facilities will be queued.
*Jun 1 06:39:36.721: //132/2CD593A881A9/SIP/State/sipSPIChangeState: 0x843AAC90 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_SENT_INVITE, SUBSTATE_NONE)
*Jun 1 06:39:36.721: //132/2CD593A881A9/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions
*Jun 1 06:39:36.725: //132/2CD593A881A9/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 132) to the VOIP RTP library
*Jun 1 06:39:36.725: //132/2CD593A881A9/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.0.20.250
*Jun 1 06:39:36.725: //132/2CD593A881A9/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1
*Jun 1 06:39:36.725: //132/2CD593A881A9/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info
laddr = 10.0.20.250, lport = 19248, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE
src_callid = 132, dest_callid = -1, stream type = voice+dtmf, stream direction = RECVONLY
media_ip_addr = 0.0.0.0
*Jun 1 06:39:36.725: //132/2CD593A881A9/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one
*Jun 1 06:39:36.729: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
INVITE sip:9000@10.0.10.50:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK862605
From: <sip:10.0.10.50>;tag=36917256-268E
To: <sip:9000@10.0.10.50>
Date: Sat, 01 Jun 2002 06:39:36 GMT
Call-ID: 2CD93EFA-746111D6-81ACF4AD-2C1F9709@10.0.20.250
Supported: 100rel,timer,replaces
Min-SE: 1800
Cisco-Guid: 752194472-1952518614-2175399085-740267785
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
CSeq: 101 INVITE
Max-Forwards: 70
Timestamp: 1022913576
Contact: <sip:10.0.20.250:5060>
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 244
v=0
o=CiscoSystemsSIP-GW-UserAgent 6608 2425 IN IP4 10.0.20.250
s=SIP Call
c=IN IP4 10.0.20.250
t=0 0
m=audio 19248 RTP/AVP 0 101
c=IN IP4 10.0.20.250
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
*Jun 1 06:39:36.733: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.0.10.50:5060
*Jun 1 06:39:36.737: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.0.10.50:5060
*Jun 1 06:39:36.737: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jun 1 06:39:36.741: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK862605
From: <sip:10.0.10.50>;tag=36917256-268E
To: <sip:9000@10.0.10.50>
Call-ID: 2CD93EFA-746111D6-81ACF4AD-2C1F9709@10.0.20.250
CSeq: 101 INVITE
Timestamp: 1022913576 0.000116
User-Agent: FreeSWITCH
Content-Length: 0
*Jun 1 06:39:36.741: //132/2CD593A881A9/SIP/State/sipSPIChangeState: 0x843AAC90 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)
*Jun 1 06:39:36.741: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jun 1 06:39:36.745: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK862605
From: <sip:10.0.10.50>;tag=36917256-268E
To: <sip:9000@10.0.10.50>;tag=FtcBr5BK6HKKH
Call-ID: 2CD93EFA-746111D6-81ACF4AD-2C1F9709@10.0.20.250
CSeq: 101 INVITE
User-Agent: FreeSWITCH
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="10.0.10.50", nonce="8410c8d0-55aa-11e9-b056-859102276f44", algorithm=MD5, qop="auth"
Content-Length: 0
*Jun 1 06:39:36.749: //132/2CD593A881A9/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer
*Jun 1 06:39:36.749: //132/2CD593A881A9/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
*Jun 1 06:39:36.749: //132/2CD593A881A9/SIP/Transport/sipSPITransportSendMessage: msg=0x845D33B0, addr=10.0.10.50, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000
*Jun 1 06:39:36.749: //132/2CD593A881A9/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jun 1 06:39:36.749: //132/2CD593A881A9/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jun 1 06:39:36.749: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x845D33B0, addr=10.0.10.50, port=5060, connId=0 for UDP
*Jun 1 06:39:36.749: //132/2CD593A881A9/SIP/Info/act_recdproc_new_message_response: Received a 4/5/6xx message with StatusCode: 407
*Jun 1 06:39:36.749: //132/2CD593A881A9/SIP/Error/sipSPIHandleAuthChallenge: Error getting credentials
*Jun 1 06:39:36.753: //132/2CD593A881A9/SIP/Error/act_recdproc_new_message_response: Error handling AuthenticationChallenge
*Jun 1 06:39:36.753: //132/2CD593A881A9/SIP/State/sipSPIChangeState: 0x843AAC90 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Jun 1 06:39:36.753: //132/2CD593A881A9/SIP/Info/ccsip_set_cc_cause_for_spi_err: Categorized cause:47, category:181
*Jun 1 06:39:36.753: //132/2CD593A881A9/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(47) for outgoing call
*Jun 1 06:39:36.753: //132/2CD593A881A9/SIP/State/sipSPIChangeState: 0x843AAC90 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Jun 1 06:39:36.753: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[132], src[6]
*Jun 1 06:39:36.765: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
ACK sip:9000@10.0.10.50:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK862605
From: <sip:10.0.10.50>;tag=36917256-268E
To: <sip:9000@10.0.10.50>;tag=FtcBr5BK6HKKH
Date: Sat, 01 Jun 2002 06:39:36 GMT
Call-ID: 2CD93EFA-746111D6-81ACF4AD-2C1F9709@10.0.20.250
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0
*Jun 1 06:39:36.765: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
*Jun 1 06:39:36.769: //132/2CD593A881A9/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:91550171 ConnTime 0
*Jun 1 06:39:36.769: //132/2CD593A881A9/SIP/State/sipSPIChangeState: 0x843AAC90 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
*Jun 1 06:39:36.773: //132/2CD593A881A9/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x843AAC90
State of The Call : STATE_DEAD
TCP Sockets Used : NO
Calling Number :
Called Number : 9000
Source IP Address (Sig ): 10.0.20.250
Destn SIP Req Addr:Port : 10.0.10.50:5060
Destn SIP Resp Addr:Port : 10.0.10.50:5060
Destination Name : 10.0.10.50
*Jun 1 06:39:36.773: //132/2CD593A881A9/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : No Codec
Negotiated Codec Bytes : 0
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0
Source IP Address (Media): 10.0.20.250
Source IP Port (Media): 19248
Destn IP Address (Media): 0.0.0.0
Destn IP Port (Media): 0
Orig Destn IP Address:Port (Media): 0.0.0.0:0
*Jun 1 06:39:36.773: //132/2CD593A881A9/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 47
Disconnect Cause (SIP) : 407
*Jun 1 06:39:36.773: //132/2CD593A881A9/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 84
*Jun 1 06:39:46.569: //128/1F983C1E81A1/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
*Jun 1 06:39:46.569: //128/1F983C1E81A1/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x843AD2BC key=1F9D1FC0-746111D6-81A4F4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:46.569: //128/1F983C1E81A1/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Jun 1 06:39:46.569: //128/1F983C1E81A1/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 843AD2BC
*Jun 1 06:39:48.696: //134/000000000000/SIP/State/sipSPIChangeState: 0x843B1F14 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Jun 1 06:39:48.700: //134/000000000000/SIP/Info/ccsip_call_setup_request:
This is a TDM-IP call: callID= 134, peer_callID = 133
*Jun 1 06:39:48.700: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP
*Jun 1 06:39:48.700: //134/33FC952481AD/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 86 to table
*Jun 1 06:39:48.705: //134/33FC952481AD/SIP/Info/act_idle_continue_call_setup:
*Jun 1 06:39:48.705: //134/33FC952481AD/SIP/Info/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec bytes: 0
*Jun 1 06:39:48.705: //134/33FC952481AD/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
*Jun 1 06:39:48.705: //134/33FC952481AD/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec
*Jun 1 06:39:48.705: //134/33FC952481AD/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp:
callid 134, channels 0x0 caps 0x0
*Jun 1 06:39:48.705: //134/33FC952481AD/SIP/Info/sipSPIValidateGtd: Signal Forward disabled
*Jun 1 06:39:48.705: //134/33FC952481AD/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0
*Jun 1 06:39:48.709: //134/33FC952481AD/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
*Jun 1 06:39:48.709: //134/33FC952481AD/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x843B1F14 key=33FFA3B5-746111D6-81B0F4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:48.709: //134/33FC952481AD/SIP/Info/sipSPIUsetBillingProfile: sipCallId for billing records = 33FFA3B5-746111D6-81B0F4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:48.709: //134/33FC952481AD/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.0.20.250
*Jun 1 06:39:48.709: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 18044 for stream 1
*Jun 1 06:39:48.709: //134/33FC952481AD/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101
*Jun 1 06:39:48.713: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20
*Jun 1 06:39:48.713: //134/33FC952481AD/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed
*Jun 1 06:39:48.713: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.0.10.50,Port 5060, Transport 1, SentBy Port 5060
*Jun 1 06:39:48.717: //134/33FC952481AD/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer
*Jun 1 06:39:48.717: //134/33FC952481AD/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
*Jun 1 06:39:48.721: //134/33FC952481AD/SIP/Transport/sipSPITransportSendMessage: msg=0x845D33B0, addr=10.0.10.50, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x80B17F40
*Jun 1 06:39:48.721: //134/33FC952481AD/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jun 1 06:39:48.721: //134/33FC952481AD/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jun 1 06:39:48.721: //134/33FC952481AD/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x845D33B0
*Jun 1 06:39:48.721: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x845D33B0, addr=10.0.10.50, port=5060, connId=1 for UDP
*Jun 1 06:39:48.721: //134/33FC952481AD/SIP/Info/sentInviteRequest: Sent Invite in state STATE_IDLE
*Jun 1 06:39:48.721: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteRequest: Transaction active. Facilities will be queued.
*Jun 1 06:39:48.721: //134/33FC952481AD/SIP/State/sipSPIChangeState: 0x843B1F14 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_SENT_INVITE, SUBSTATE_NONE)
*Jun 1 06:39:48.721: //134/33FC952481AD/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions
*Jun 1 06:39:48.721: //134/33FC952481AD/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 134) to the VOIP RTP library
*Jun 1 06:39:48.725: //134/33FC952481AD/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.0.20.250
*Jun 1 06:39:48.725: //134/33FC952481AD/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1
*Jun 1 06:39:48.725: //134/33FC952481AD/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info
laddr = 10.0.20.250, lport = 18044, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE
src_callid = 134, dest_callid = -1, stream type = voice+dtmf, stream direction = RECVONLY
media_ip_addr = 0.0.0.0
*Jun 1 06:39:48.725: //134/33FC952481AD/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one
*Jun 1 06:39:48.729: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
INVITE sip:9000@10.0.10.50:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK8723A2
From: <sip:10.0.10.50>;tag=3691A136-2B
To: <sip:9000@10.0.10.50>
Date: Sat, 01 Jun 2002 06:39:48 GMT
Call-ID: 33FFA3B5-746111D6-81B0F4AD-2C1F9709@10.0.20.250
Supported: 100rel,timer,replaces
Min-SE: 1800
Cisco-Guid: 872191268-1952518614-2175661229-740267785
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
CSeq: 101 INVITE
Max-Forwards: 70
Timestamp: 1022913588
Contact: <sip:10.0.20.250:5060>
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 244
v=0
o=CiscoSystemsSIP-GW-UserAgent 6289 5620 IN IP4 10.0.20.250
s=SIP Call
c=IN IP4 10.0.20.250
t=0 0
m=audio 18044 RTP/AVP 0 101
c=IN IP4 10.0.20.250
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
*Jun 1 06:39:48.733: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.0.10.50:5060
*Jun 1 06:39:48.737: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.0.10.50:5060
*Jun 1 06:39:48.737: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jun 1 06:39:48.741: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK8723A2
From: <sip:10.0.10.50>;tag=3691A136-2B
To: <sip:9000@10.0.10.50>
Call-ID: 33FFA3B5-746111D6-81B0F4AD-2C1F9709@10.0.20.250
CSeq: 101 INVITE
Timestamp: 1022913588 0.000101
User-Agent: FreeSWITCH
Content-Length: 0
*Jun 1 06:39:48.741: //134/33FC952481AD/SIP/State/sipSPIChangeState: 0x843B1F14 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)
*Jun 1 06:39:48.741: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Jun 1 06:39:48.745: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK8723A2
From: <sip:10.0.10.50>;tag=3691A136-2B
To: <sip:9000@10.0.10.50>;tag=g353S0vp3t95c
Call-ID: 33FFA3B5-746111D6-81B0F4AD-2C1F9709@10.0.20.250
CSeq: 101 INVITE
User-Agent: FreeSWITCH
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="10.0.10.50", nonce="8b37c7d0-55aa-11e9-b058-859102276f44", algorithm=MD5, qop="auth"
Content-Length: 0
*Jun 1 06:39:48.749: //134/33FC952481AD/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer
*Jun 1 06:39:48.749: //134/33FC952481AD/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
*Jun 1 06:39:48.749: //134/33FC952481AD/SIP/Transport/sipSPITransportSendMessage: msg=0x845D3B00, addr=10.0.10.50, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000
*Jun 1 06:39:48.749: //134/33FC952481AD/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Jun 1 06:39:48.749: //134/33FC952481AD/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Jun 1 06:39:48.749: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x845D3B00, addr=10.0.10.50, port=5060, connId=0 for UDP
*Jun 1 06:39:48.749: //134/33FC952481AD/SIP/Info/act_recdproc_new_message_response: Received a 4/5/6xx message with StatusCode: 407
*Jun 1 06:39:48.749: //134/33FC952481AD/SIP/Error/sipSPIHandleAuthChallenge: Error getting credentials
*Jun 1 06:39:48.753: //134/33FC952481AD/SIP/Error/act_recdproc_new_message_response: Error handling AuthenticationChallenge
*Jun 1 06:39:48.753: //134/33FC952481AD/SIP/State/sipSPIChangeState: 0x843B1F14 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Jun 1 06:39:48.753: //134/33FC952481AD/SIP/Info/ccsip_set_cc_cause_for_spi_err: Categorized cause:47, category:181
*Jun 1 06:39:48.753: //134/33FC952481AD/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(47) for outgoing call
*Jun 1 06:39:48.753: //134/33FC952481AD/SIP/State/sipSPIChangeState: 0x843B1F14 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Jun 1 06:39:48.753: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[134], src[6]
*Jun 1 06:39:48.757: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
ACK sip:9000@10.0.10.50:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.20.250:5060;branch=z9hG4bK8723A2
From: <sip:10.0.10.50>;tag=3691A136-2B
To: <sip:9000@10.0.10.50>;tag=g353S0vp3t95c
Date: Sat, 01 Jun 2002 06:39:48 GMT
Call-ID: 33FFA3B5-746111D6-81B0F4AD-2C1F9709@10.0.20.250
Max-Forwards: 70
CSeq: 101 ACK
Content-Length: 0
*Jun 1 06:39:48.761: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
*Jun 1 06:39:48.761: //134/33FC952481AD/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:91551370 ConnTime 0
*Jun 1 06:39:48.765: //134/33FC952481AD/SIP/State/sipSPIChangeState: 0x843B1F14 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
*Jun 1 06:39:48.765: //134/33FC952481AD/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x843B1F14
State of The Call : STATE_DEAD
TCP Sockets Used : NO
Calling Number :
Called Number : 9000
Source IP Address (Sig ): 10.0.20.250
Destn SIP Req Addr:Port : 10.0.10.50:5060
Destn SIP Resp Addr:Port : 10.0.10.50:5060
Destination Name : 10.0.10.50
*Jun 1 06:39:48.765: //134/33FC952481AD/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : No Codec
Negotiated Codec Bytes : 0
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0
Source IP Address (Media): 10.0.20.250
Source IP Port (Media): 18044
Destn IP Address (Media): 0.0.0.0
Destn IP Port (Media): 0
Orig Destn IP Address:Port (Media): 0.0.0.0:0
*Jun 1 06:39:48.765: //134/33FC952481AD/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 47
Disconnect Cause (SIP) : 407
*Jun 1 06:39:48.765: //134/33FC952481AD/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 86
*Jun 1 06:39:56.710: //130/25A5671081A5/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
*Jun 1 06:39:56.710: //130/25A5671081A5/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x843A6038 key=25A91262-746111D6-81A8F4AD-2C1F9709@10.0.20.250
*Jun 1 06:39:56.710: //130/25A5671081A5/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Jun 1 06:39:56.710: //130/25A5671081A5/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 843A6038
*Jun 1 06:40:08.773: //132/2CD593A881A9/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
*Jun 1 06:40:08.773: //132/2CD593A881A9/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x843AAC90 key=2CD93EFA-746111D6-81ACF4AD-2C1F9709@10.0.20.250
*Jun 1 06:40:08.773: //132/2CD593A881A9/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Jun 1 06:40:08.773: //132/2CD593A881A9/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 843AAC90And FS displays this in its debug logs:
Code:
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/nobody@10.0.10.50) State DESTROY going to sleep
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:181 sofia/internal/nobody@10.0.10.50 Standard DESTROY
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] mod_sofia.c:343 sofia/internal/nobody@10.0.10.50 SOFIA DESTROY
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/nobody@10.0.10.50) State DESTROY
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/nobody@10.0.10.50) Running State Change CS_DESTROY (Cur 0 Tot 10)
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/nobody@10.0.10.50 [CS_DESTROY]
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [NOTICE] switch_core_session.c:1683 Session 10 (sofia/internal/nobody@10.0.10.50) Ended
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_session.c:1665 Session 10 (sofia/internal/nobody@10.0.10.50) Locked, Waiting on external entities
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/nobody@10.0.10.50) State Change CS_REPORTING -> CS_DESTROY
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/nobody@10.0.10.50) State REPORTING going to sleep
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:174 sofia/internal/nobody@10.0.10.50 Standard REPORTING, cause: WRONG_CALL_STATE
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/nobody@10.0.10.50) State REPORTING
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/nobody@10.0.10.50) Running State Change CS_REPORTING (Cur 1 Tot 10)
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/nobody@10.0.10.50) State Change CS_HANGUP -> CS_REPORTING
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/nobody@10.0.10.50) State HANGUP going to sleep
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:60 sofia/internal/nobody@10.0.10.50 Standard HANGUP, cause: WRONG_CALL_STATE
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] mod_sofia.c:438 Channel sofia/internal/nobody@10.0.10.50 hanging up, cause: WRONG_CALL_STATE
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/nobody@10.0.10.50) State HANGUP
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/nobody@10.0.10.50) Callstate Change DOWN -> HANGUP
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/nobody@10.0.10.50) Running State Change CS_HANGUP (Cur 1 Tot 10)
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/internal/nobody@10.0.10.50 [CS_NEW] [WRONG_CALL_STATE]
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:44.011064 [WARNING] switch_core_state_machine.c:687 7ce0e234-55aa-11e9-b053-859102276f44 sofia/internal/nobody@10.0.10.50 Abandoned
2019-04-02 17:50:33.930911 [DEBUG] sofia.c:2334 detaching session 7ce0e234-55aa-11e9-b053-859102276f44
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:33.930911 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/nobody@10.0.10.50) State NEW
2019-04-02 17:50:33.930911 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [9000@10.0.10.50] from ip 10.0.20.250
2019-04-02 17:50:33.930911 [DEBUG] sofia.c:10044 IP 10.0.20.250 Rejected by acl "domains". Falling back to Digest auth.
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:33.930911 [DEBUG] sofia.c:9873 sofia/internal/nobody@10.0.10.50 receiving invite from 10.0.20.250:58812 version: 1.6.20 64bit
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:33.930911 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/nobody@10.0.10.50) Running State Change CS_NEW (Cur 1 Tot 10)
7ce0e234-55aa-11e9-b053-859102276f44 2019-04-02 17:50:33.930911 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/nobody@10.0.10.50 [7ce0e234-55aa-11e9-b053-859102276f44]
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/5416599905@10.0.10.50) State DESTROY going to sleep
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:181 sofia/internal/5416599905@10.0.10.50 Standard DESTROY
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] mod_sofia.c:343 sofia/internal/5416599905@10.0.10.50 SOFIA DESTROY
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/5416599905@10.0.10.50) State DESTROY
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/5416599905@10.0.10.50) Running State Change CS_DESTROY (Cur 0 Tot 9)
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/5416599905@10.0.10.50 [CS_DESTROY]
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [NOTICE] switch_core_session.c:1683 Session 9 (sofia/internal/5416599905@10.0.10.50) Ended
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_session.c:1665 Session 9 (sofia/internal/5416599905@10.0.10.50) Locked, Waiting on external entities
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/5416599905@10.0.10.50) State Change CS_REPORTING -> CS_DESTROY
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/5416599905@10.0.10.50) State REPORTING going to sleep
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:174 sofia/internal/5416599905@10.0.10.50 Standard REPORTING, cause: WRONG_CALL_STATE
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/5416599905@10.0.10.50) State REPORTING
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/5416599905@10.0.10.50) Running State Change CS_REPORTING (Cur 1 Tot 9)
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/5416599905@10.0.10.50) State Change CS_HANGUP -> CS_REPORTING
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/5416599905@10.0.10.50) State HANGUP going to sleep
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:60 sofia/internal/5416599905@10.0.10.50 Standard HANGUP, cause: WRONG_CALL_STATE
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] mod_sofia.c:438 Channel sofia/internal/5416599905@10.0.10.50 hanging up, cause: WRONG_CALL_STATE
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/5416599905@10.0.10.50) State HANGUP
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/5416599905@10.0.10.50) Callstate Change DOWN -> HANGUP
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/5416599905@10.0.10.50) Running State Change CS_HANGUP (Cur 1 Tot 9)
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/internal/5416599905@10.0.10.50 [CS_NEW] [WRONG_CALL_STATE]
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:33.871041 [WARNING] switch_core_state_machine.c:687 76d5c1fc-55aa-11e9-b051-859102276f44 sofia/internal/5416599905@10.0.10.50 Abandoned
2019-04-02 17:50:23.790989 [DEBUG] sofia.c:2334 detaching session 76d5c1fc-55aa-11e9-b051-859102276f44
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:23.790989 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/5416599905@10.0.10.50) State NEW
2019-04-02 17:50:23.790989 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [9000@10.0.10.50] from ip 10.0.20.250
2019-04-02 17:50:23.790989 [DEBUG] sofia.c:10044 IP 10.0.20.250 Rejected by acl "domains". Falling back to Digest auth.
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:23.790989 [DEBUG] sofia.c:9873 sofia/internal/5416599905@10.0.10.50 receiving invite from 10.0.20.250:58812 version: 1.6.20 64bit
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:23.790989 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/5416599905@10.0.10.50) Running State Change CS_NEW (Cur 1 Tot 9)
76d5c1fc-55aa-11e9-b051-859102276f44 2019-04-02 17:50:23.790989 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/5416599905@10.0.10.50 [76d5c1fc-55aa-11e9-b051-859102276f44]The way I translate all this is that FS wont call out to the 1760V because of some kind of misconfiguration, and when I call in from the PSTN, the 1760V's config is sound, but when FS recieves the session, because of a misconfiguration it either cant or wont handle the call and process it.
Any ideas folks?
Attachments
Last edited: