Re: CUBE Phone-Proxy on IRS4300 running 16.05.01b

jtwardowski · ‎09-18-2018

Greetings, wonder if anyone can help with IRS4300 running 16.05.01b version.

Trying to work out phone-proxy configuration for the "outside" phones being able to register to cucm.

CUCM running 11.5 (pub and sub), inside interface on 4300 L2 to CUCM.

I was following several docs, only all them are related to 15.x configs:

http://www.cisco.com/c/en/us/td/docs/ios-xml/ios/voice/cube_interop/configuration/15-mt/cube-interop-15-mt-book/voi-cucm-lineside.html#reference_956BE6CA0F3A43EB9D7E538ABE666177
https://ciscocollab.wordpress.com/2014/04/08/cube-sip-lineside-phone-vpn-configuration/
https://www.cisco.com/c/en/us/support/docs/unified-communications/unified-border-element/200213-Configure-and-Troubleshoot-CUBE-SIP-Line.html.

I'm still confused about certs that should be used....

Also, maybe anyone can point me to proxy config doc for ver 16.x?

One issue i run in to is related to CUCM pub. It's using name, not IP which was the issues with ver 15.x

I try to point flow to CUCM sub that is using IP as work around, not sure if that may play any role.

I would appreciate any assistance/help with getting this resolved.

At this point i come with the following configuration:

crypto pki trustpoint selfsign
enrollment selfsigned
subject-name CN=CUBE01 CN=IPONE
revocation-check none
rsakeypair selfsign
!
crypto pki trustpoint ccm1
enrollment terminal
revocation-check none
!
crypto pki trustpoint Cisco_Manufacturing_CA
enrollment terminal
revocation-check none
!
crypto pki trustpoint ccm11
enrollment terminal
revocation-check none
!
crypto pki trustpoint capf11
enrollment terminal
revocation-check none
!
!
crypto pki certificate chain selfsign
certificate self-signed 01
<ommited>
crypto pki certificate chain ccm1
certificate ca 756449853083DC104B5F8CEA2DB31BAB
<ommited>
crypto pki certificate chain Cisco_Manufacturing_CA
certificate ca 6A6967B3000000000003
<ommited>
crypto pki certificate chain ccm11
<ommited>
crypto pki certificate chain capf11
certificate ca 79B0BD03DC22CBD5A85E26DC5FC8CFE1
<ommited>
!
!
!
voice service voip
no ip address trusted authenticate
allow-connections sip to sip
fax protocol t38 version 0 ls-redundancy 0 hs-redundancy 0 fallback none
sip
session transport tcp
header-passing
registrar server
nat auto
pass-thru headers unsupp
pass-thru subscribe-notify-events all
pass-thru content unsupp
registration passthrough
extension cucm
!
!
voice class uri 1 sip
host ipv4:<pub_ip>
!
voice class uri 2 sip
host ipv4:<local_ip>
!
voice class uri 3 sip
host ipv4:<cucm_ip>
!
voice class sip-profiles 10
request INVITE peer-header sip contact copy ">(;.*)" u01
request REGISTER peer-header sip contact copy ">(;.*)" u02
request INVITE sip-header Cisco-Guid remove
request INVITE sip-header Contact modify "(.*)" "\1\u10"
request REGISTER sip-header Contact modify "(.*)" "\1\u20"
!
voice class sip-profiles 11
request INVITE peer-header sip contact copy ">(;.*)" u01
request INVITE peer-header sip SIP-Req-URI copy "sip:([^@]*)@" u02
response 200 peer-header sip contact copy ">(;.*)" u03
request CANCEL peer-header sip SIP-Req-URI copy "sip:([^@]*)@" u04
request INVITE sip-header Cisco-Guid remove
request INVITE sip-header Contact modify "(.)*" "\1\u10"
response 200 sip-header Contact modify "(.)*" "\1\u30"
request CANCEL sip-header SIP-Req-URI modify ".*" "INVITE sip:\u0<pub_ip> SIP/2.0"
response 200 sip-header Contact modify "(.*)" "\1\u30"
request CANCEL sip-header SIP-Req-URI modify "*." "CANCEL sip:\u04<cucm-ip> SIP/2.0"
!
!
voice class sip-hdr-passthrulist 10
passthru-hdr Remote-Pary-ID
passthru-hdr Call-Info
passthru-hdr Content-ID
passthru-hdr supported
passthru-hdr require
passthru-hdr Referred-By
!
voice class sip-copylist 10
sip-header SIP-Req-URI
sip-header contact
!
voice class sip-copylist 11
sip-header contact

interface GigabitEthernet0/0/0
ip address <pub_ip>
speed 10
no negotiation auto
!
interface GigabitEthernet0/0/1
ip address <local_ip>
negotiation auto
!

dspfarm profile 1 transcode universal
associate application CUBE
shutdown
voice-ctl-file ctl_secure
record-entry selfsigned trustpoint selfsign
record-entry cucm-tftp trustpoint ccm11
record-entry capf trustpoint capf11
complete
voice-phone-proxy cube01
tftp-server address ipv4 <cucm_ip> local-addr ipv4 <local_ip> acc-addr ipv4 <pub_ip>
ctl-file ctl_secure
access-secure
service-map server-addr ipv4 <cucm_ip> port 8443 acc-addr ipv4 209.29.5.21 port 8443
service-map server-addr ipv4 <cucm_ip> port 8080 acc-addr ipv4 209.29.5.21 port 8080
service-map server-addr ipv4 <cucm_ip> port 3804 acc-addr ipv4 209.29.5.21 port 3804
complete
voice-phone-proxy tftp-address ipv4 <local_ip>
port-range 30000 60000
voice-phone-proxy tftp-address ipv4 <pub_ip>
port-range 30000 60000
voice-phone-proxy file-buffer size 60
!
dial-peer voice 2 voip
description DP_facing_CCM
session protocol sipv2
session target ipv4:<cucm_ip>
session transport tcp
destination uri 1
incoming uri via 3
voice-class sip extension cucm
voice-class sip call-route url
voice-class sip profiles 11
voice-class sip pass-thru headers 10
voice-class sip copy-list 11
dtmf-relay rtp-nte
codec transparent
!
dial-peer voice 1 voip
phone-proxy cube01 signal-addr ipv4 <pub_ip> cucm ipv4 <cucm_ip>
description *** Dialpeer Facing Outside ***
session protocol sipv2
session target registrar
session transport tcp
destination uri 2
incoming uri request 1
voice-class sip call-route url
voice-class sip profiles 10
voice-class sip registration passthrough registrar-index 1
voice-class sip pass-thru headers 10
voice-class sip copy-list 10
dtmf-relay rtp-nte
codec transparent
!
!
sip-ua
timers connection aging 60
registrar 1 ipv4:<cucm_ip> expires 3600 refresh-ratio 100 tcp
!

Phones are not able to register, phone-proxy debug shows the following:

*Sep 18 15:08:41.208: Phone proxy new phone event handler 1
*Sep 18 15:08:41.208: Phone proxy: TCP Socket accept
*Sep 18 15:08:41.208: Create device hash table for phone <phone_ip> : 49642
*Sep 18 15:08:41.208: TCP access socket inherit fd:0 from fd:5
*Sep 18 15:08:41.208: pp_add_tcp_access_socket session 0x7F7220283A60 access side raddr:<phone_ip>, socket:0

*Sep 18 15:08:41.210: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:08:41.210: access socket recv http:GET /SEP247E12BFD0CD.cnf.xml.sgn HTTP/1.1
Host:<pub_ip>:6970

*Sep 18 15:08:41.210: PP: Remote phone from <phone_ip>/49642 requesting GET /SEP247E12BFD0CD.cnf.xml.sgn HTTP/1.1
Host:<pub_ip>:6970

at <pub_ip>/6970

*Sep 18 15:08:41.210: get file name:SEP247E12BFD0CD.cnf.xml.sgn

*Sep 18 15:08:41.210: core side ip <cucm_ip> session 0x7F7220283A60

*Sep 18 15:08:41.211: PP socket connect 1 remote addr <cucm_ip> port 6970

*Sep 18 15:08:41.211: PP socket connect 1 remote addr <cucm_ip> port 6970 in progress

*Sep 18 15:08:41.211: pp_add_tcp_core_socket session 0x7F7220283A60 core side raddr:<cucm_ip>, socket:1
*Sep 18 15:08:41.211: PP: The remote phone is requesting file SEP247E12BFD0CD.cnf.xml.sgn.
PP: Removing .sgn extension, SBC is requesting file SEP247E12BFD0CD.cnf.xml.sgn from Call Manager HTTP server.

*Sep 18 15:08:41.211: PP: SBC sent request for SEP247E12BFD0CD.cnf.xml.sgn sourced from 10.26.200.30:40047 to <cucm_ip>:6970, vrf Global

*Sep 18 15:08:41.211: PP: modify http host, header:GET /SEP247E12BFD0CD.cnf.xml HTTP/1.1
Host:<cucm_ip>:6970

, size: 65
*Sep 18 15:08:41.211: Phoneproxy tried to send data 0x7F72202D7340 65 bytes, socket 1 sent nothing,tcp connect not finished
*Sep 18 15:08:41.212: Got socket write event to resend on socket fd 1 resend queue:0x7F721D1FE410
*Sep 18 15:08:41.212: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:08:41.219: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:08:41.219: http core side first pkg
*Sep 18 15:08:41.219: http 200OK msg size:12997process http core side didn't finish,will continue process
*Sep 18 15:08:41.220: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60process http core side didn't finish,will continue process
*Sep 18 15:08:41.220: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60process http core side didn't finish,will continue process
*Sep 18 15:08:41.221: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60process http core side didn't finish,will continue process
*Sep 18 15:08:41.222: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60process http core side didn't finish,will continue process
*Sep 18 15:08:41.223: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:08:41.223: PP: Complete configuration file received from Call Manager TFTP server, beginning config file modification process.

*Sep 18 15:08:41.223: PP: Config Modify: rewriting addr to <cucm_ip>

*Sep 18 15:08:41.223: PP: Config Modify: rewriting addr to 0.0.0.0

*Sep 18 15:08:41.223: PP: CM Name Config Modify : detected Call Manager Name.
*Sep 18 15:08:41.223: PP: Config Modify: rewriting addr to <cucm_ip>

*Sep 18 15:08:41.223: PP: Config Modify: rewriting addr to <pub_ip>

*Sep 18 15:08:41.223: PP: CM Name Config Modify : detected Call Manager Name.
*Sep 18 15:08:41.223: PP: Config Modify: rewriting port 5060 to 5060

*Sep 18 15:08:41.223: PP: Config Modify: rewriting port 5061 to 5061

*Sep 18 15:08:41.223: PP: Config Modify: rewriting addr to <cucm_ip>

*Sep 18 15:08:41.224: PP: Config Modify: rewriting addr to <pub_ip>

*Sep 18 15:08:41.224: PP: CM Config Modify : detected Call Manager Node Name.
*Sep 18 15:08:41.224: PP: Config Modify: rewriting addr to <cucm_ip>

*Sep 18 15:08:41.224: PP: Config Modify: rewriting addr to 0.0.0.0

*Sep 18 15:08:41.224: PP: CM Name Config Modify : detected Call Manager Name.
*Sep 18 15:08:41.224: PP: Config Modify: rewriting port 5060 to 5060

*Sep 18 15:08:41.224: PP: Config Modify: rewriting port 5061 to 5061

*Sep 18 15:08:41.224: PP: Config Modify: rewriting addr to <cucm_ip>

*Sep 18 15:08:41.224: PP: Config Modify: rewriting addr to 0.0.0.0

*Sep 18 15:08:41.224: PP: Config Modify : detected Call Manager Node Name.
*Sep 18 15:08:41.224: PP: Config Modify : deviceSecurityMode set to 1 (unencrypted), modifying deviceSecurityMode to 3 (encrypted).

*Sep 18 15:08:41.224: PP: Url ipaddr invalid ip addr
*Sep 18 15:08:41.224: PP: Url ipaddr invalid ip addr
*Sep 18 15:08:41.224: PP: Url ipaddr invalid ip addr
*Sep 18 15:08:41.224: PP: Url ipaddr invalid ip addr
*Sep 18 15:08:41.224: PP: Url ipaddr invalid ip addr
*Sep 18 15:08:41.225: PP: Url ipaddr invalid ip addr
*Sep 18 15:08:41.225: PP: Url ipaddr invalid ip addr
*Sep 18 15:08:41.225: PP: Url ipaddr invalid ip addr
*Sep 18 15:08:41.225: PP: Config Modify : Modifying to TLS as the transport layer protocol.

*Sep 18 15:08:41.225: PP: Config Modify: rewriting addr to 0.0.0.0

*Sep 18 15:08:41.225: PP:CAPF Config Modify : detected Call Manager Node Name. Enter ctl_sign
PP: Encrypting and signing modified config file using trustpoint <selfsign>.
ctl_sign: total_file_len=13323, signature_len = 128

*Sep 18 15:08:41.230: PP: Data sent from <pub_ip>/6970 to remote phone at <phone_ip>/49642
process http core side succ,delete socket
*Sep 18 15:08:41.231: PP delete session:0x7F7220283A60, core:0, access:1
*Sep 18 15:08:41.251: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.253: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.270: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.275: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.276: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.291: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.297: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.299: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.301: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.313: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.319: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.321: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.323: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.325: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.327: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:41.380: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:08:41.380: PP delete session:0x7F7220283A60, core:0, access:0
*Sep 18 15:08:41.380: Remove device hash table for phone <phone_ip> : 49642
*Sep 18 15:08:43.911: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:08:43.930: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:08:43.930: Phone proxy new phone event handler 1
*Sep 18 15:08:43.930: Phone proxy: TCP Socket accept
*Sep 18 15:08:43.930: Create device hash table for phone <phone_ip> : 49643
*Sep 18 15:08:43.930: TCP access socket inherit fd:0 from fd:5
*Sep 18 15:08:43.930: pp_add_tcp_access_socket session 0x7F7220283A60 access side raddr:<phone_ip>, socket:0

*Sep 18 15:08:43.932: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:08:43.932: access socket recv http:GET /Canada/g3-tones.xml.sgn HTTP/1.1
Host:<pub_ip>:6970

*Sep 18 15:08:43.932: PP: Remote phone from <phone_ip>/49643 requesting GET /Canada/g3-tones.xml.sgn HTTP/1.1
Host:<pub_ip>:6970

at <pub_ip>/6970

*Sep 18 15:08:43.932: get file name:Canada/g3-tones.xml.sgn

*Sep 18 15:08:43.932: DBG: check if filename(Canada/g3-tones.xml.sgn) buffered
*Sep 18 15:08:43.932: core side ip <cucm_ip> session 0x7F7220283A60

*Sep 18 15:08:43.932: PP socket connect 1 remote addr <cucm_ip> port 6970

*Sep 18 15:08:43.933: PP socket connect 1 remote addr <cucm_ip> port 6970 in progress

*Sep 18 15:08:43.933: pp_add_tcp_core_socket session 0x7F7220283A60 core side raddr:<cucm_ip>, socket:1
*Sep 18 15:08:43.933: PP: SBC sent request for Canada/g3-tones.xml.sgn sourced from 10.26.200.30:40048 to <cucm_ip>:6970, vrf Global

*Sep 18 15:08:43.933: PP: modify http host, header:GET /Canada/g3-tones.xml.sgn HTTP/1.1
Host:<cucm_ip>:6970

, size: 65
*Sep 18 15:08:43.933: Phoneproxy tried to send data 0x7F72202D7340 65 bytes, socket 1 sent nothing,tcp connect not finished
*Sep 18 15:08:43.933: Got socket write event to resend on socket fd 1 resend queue:0x7F721D1FE410
*Sep 18 15:08:43.934: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:08:43.935: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:08:43.935: http core side first pkg
*Sep 18 15:08:43.935: http error msg
*Sep 18 15:08:43.935: PP: Data sent from <pub_ip>/6970 to remote phone at <phone_ip>/49643
process http core side succ,delete socket
*Sep 18 15:08:43.935: PP delete session:0x7F7220283A60, core:0, access:1
*Sep 18 15:08:43.956: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:08:43.956: PP delete session:0x7F7220283A60, core:0, access:0
*Sep 18 15:08:43.956: Remove device hash table for phone <phone_ip> : 49643
*Sep 18 15:08:44.337: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:08:44.356: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:08:44.356: Phone proxy new phone event handler 1
*Sep 18 15:08:44.356: Phone proxy: TCP Socket accept
*Sep 18 15:08:44.356: Create device hash table for phone <phone_ip> : 49644
*Sep 18 15:08:44.356: TCP access socket inherit fd:0 from fd:5
*Sep 18 15:08:44.356: pp_add_tcp_access_socket session 0x7F7220283A60 access side raddr:<phone_ip>, socket:0

*Sep 18 15:08:44.357: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:08:44.358: access socket recv http:GET /AppDialRules.xml HTTP/1.1
Host:<pub_ip>:6970

*Sep 18 15:08:44.358: PP: Remote phone from <phone_ip>/49644 requesting GET /AppDialRules.xml HTTP/1.1
Host:<pub_ip>:6970

at <pub_ip>/6970

*Sep 18 15:08:44.358: get file name:AppDialRules.xml

*Sep 18 15:08:44.358: DBG: check if filename(AppDialRules.xml) buffered
*Sep 18 15:08:44.358: DBG: filename(AppDialRules.xml) has been buffered
*Sep 18 15:08:44.358: DBG: register filename(AppDialRules.xml) event(2) session(0x7F7220283A60) callback
*Sep 18 15:08:44.358: DBG: register filename(AppDialRules.xml) event(1) session(0x7F7220283A60) callback
*Sep 18 15:08:44.358: PP: Data sent from <pub_ip>/6970 to remote phone at <phone_ip>/49644

*Sep 18 15:08:44.397: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:08:44.397: PP delete session:0x7F7220283A60, core:0, access:0
*Sep 18 15:08:44.397: DBG: unregister filename(AppDialRules.xml) event(3) session(0x7F7220283A60) callback
*Sep 18 15:08:44.397: Remove device hash table for phone <phone_ip> : 49644
*Sep 18 15:08:44.505: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:08:44.524: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:08:44.524: Phone proxy new phone event handler 1
*Sep 18 15:08:44.524: Phone proxy: TCP Socket accept
*Sep 18 15:08:44.524: Create device hash table for phone <phone_ip> : 49645
*Sep 18 15:08:44.524: TCP access socket inherit fd:0 from fd:5
*Sep 18 15:08:44.524: pp_add_tcp_access_socket session 0x7F7220283A60 access side raddr:<phone_ip>, socket:0

*Sep 18 15:08:44.526: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:08:44.526: access socket recv http:GET /SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml.sgn HTTP/1.1
Host:<pub_ip>:6970

*Sep 18 15:08:44.526: PP: Remote phone from <phone_ip>/49645 requesting GET /SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml.sgn HTTP/1.1
Host:<pub_ip>:6970

at <pub_ip>/6970

*Sep 18 15:08:44.526: get file name:SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml.sgn

*Sep 18 15:08:44.527: DBG: check if filename(SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml.sgn) buffered
*Sep 18 15:08:44.527: DBG: filename(SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml.sgn) has been buffered
*Sep 18 15:08:44.527: DBG: register filename(SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml.sgn) event(2) session(0x7F7220283A60) callback
*Sep 18 15:08:44.527: DBG: register filename(SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml.sgn) event(1) session(0x7F7220283A60) callback
*Sep 18 15:08:44.527: PP: Data sent from <pub_ip>/6970 to remote phone at <phone_ip>/49645

*Sep 18 15:08:44.546: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:44.549: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:44.566: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:44.571: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:44.572: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:44.587: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:44.594: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE4F0
*Sep 18 15:08:44.639: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:08:44.639: PP delete session:0x7F7220283A60, core:0, access:0
*Sep 18 15:08:44.639: DBG: unregister filename(SK72f64050-7ad5-4b47-9bfa-5e9ad9cd4aa9.xml.sgn) event(3) session(0x7F7220283A60) callback
*Sep 18 15:08:44.639: Remove device hash table for phone <phone_ip> : 49645
*Sep 18 15:09:06.160: pp: file buffer manager 7F7213E16590 aging timer expired
*Sep 18 15:09:06.160: DBG: file buffer aging timeout, buffer total_size(14763), file_num(3)
*Sep 18 15:09:06.161: DBG: current hash elem num 3
*Sep 18 15:09:06.161: DBG: restart file buffer aging timer

R0g22 · ‎09-18-2018

Didn't go through the logs but I will point out a couple of things -

1. Phone Proxy only supports 1024 bit encryption.
2. Ensure you don't have a SIP trunk on CUCM pointing to the CORE IP of CUBE. Registrations will be rejected.

Additionally, there are concerns regarding your phone proxy config. I am highlighting them below -

voice-phone-proxy cube01
tftp-server address ipv4 <cucm_ip> local-addr ipv4 <local_ip> acc-addr ipv4 <pub_ip>
ctl-file ctl_secure
access-secure
service-map server-addr ipv4 <cucm_ip> port 8443 acc-addr ipv4 209.29.5.21 port 8443
service-map server-addr ipv4 <cucm_ip> port 8080 acc-addr ipv4 209.29.5.21 port 8080
service-map server-addr ipv4 <cucm_ip> port 3804 acc-addr ipv4 209.29.5.21 port 3804
complete
voice-phone-proxy tftp-address ipv4 <local_ip>
port-range 30000 60000
voice-phone-proxy tftp-address ipv4 <pub_ip>
port-range 30000 60000

<local_ip> needs to be replaced with a CUBE core IP
<pub_ip> needs to be replaced with the CUBE access IP
acc-addr ipv4 209.29.5.21 >> this needs to be CUBE access IP

These changes need to be made throughout the config including dial-peers and sip uri.

In case you are wondering what the CORE and ACCESS ip addresses need to be -

CORE IP is the internal CUBE address used to connect to CUCM
ACCESS IP is for the interface that the remote phones will connect to.

jtwardowski · ‎09-18-2018

it looks like my IP cleanup didn't work:-(
Anyhow, IPs are set as required.
In regards to 1024bit, that was clearly stated in one of the documents and i followed up with proper selfsigned 1024 cert.
209.29.5.21 is cube public (test)
<local_ip> is 10.26.200.30 = core ip
<cucm_ip> is 10.26.200.10 (pub)
Regards

R0g22 · ‎09-18-2018

The logs that you collected were with the correct config or corrected the confiig after reading my post ?

jtwardowski · ‎09-18-2018

logs were collected with proper configuration. I just replaced IPs with genetic <device_ip> for the posting purpose.
For clarification i added IPs since removing/replacing them created some confusion.
Here is log in original version:

Sep 18 15:39:38.113: Phone proxy new phone event handler 1
*Sep 18 15:39:38.113: Phone proxy: TCP Socket accept
*Sep 18 15:39:38.113: Create device hash table for phone 69.156.48.65 : 49712
*Sep 18 15:39:38.113: TCP access socket inherit fd:0 from fd:5
*Sep 18 15:39:38.113: pp_add_tcp_access_socket session 0x7F7220283A60 access side raddr:69.156.48.65, socket:0

*Sep 18 15:39:38.114: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:39:38.114: access socket recv http:GET /CTLSEP247E12BFD0CD.tlv HTTP/1.1
Host:209.29.5.21:6970

*Sep 18 15:39:38.114: PP: Remote phone from 69.156.48.65/49712 requesting GET /CTLSEP247E12BFD0CD.tlv HTTP/1.1
Host:209.29.5.21:6970

at 209.29.5.21/6970

*Sep 18 15:39:38.114: get file name:CTLSEP247E12BFD0CD.tlv

*Sep 18 15:39:38.114: this is ctl file
*Sep 18 15:39:38.115: PP: send http ctl file
*Sep 18 15:39:38.137: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.159: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.161: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.182: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.184: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.186: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.231: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:39:38.232: PP delete session:0x7F7220283A60, core:0, access:0
*Sep 18 15:39:38.374: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:39:38.392: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:39:38.392: Phone proxy new phone event handler 1
*Sep 18 15:39:38.392: Phone proxy: TCP Socket accept
*Sep 18 15:39:38.393: Create device hash table for phone 69.156.48.65 : 49713
*Sep 18 15:39:38.393: TCP access socket inherit fd:0 from fd:5
*Sep 18 15:39:38.393: pp_add_tcp_access_socket session 0x7F7220283A60 access side raddr:69.156.48.65, socket:0

*Sep 18 15:39:38.394: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:39:38.394: access socket recv http:GET /ITLSEP247E12BFD0CD.tlv HTTP/1.1
Host:209.29.5.21:6970

*Sep 18 15:39:38.395: PP: Remote phone from 69.156.48.65/49713 requesting GET /ITLSEP247E12BFD0CD.tlv HTTP/1.1
Host:209.29.5.21:6970

at 209.29.5.21/6970

*Sep 18 15:39:38.395: get file name:ITLSEP247E12BFD0CD.tlv

*Sep 18 15:39:38.395: DBG: check if filename(ITLSEP247E12BFD0CD.tlv) buffered
*Sep 18 15:39:38.395: DBG: filename(ITLSEP247E12BFD0CD.tlv) has been buffered
*Sep 18 15:39:38.395: DBG: register filename(ITLSEP247E12BFD0CD.tlv) event(2) session(0x7F7220283A60) callback
*Sep 18 15:39:38.395: DBG: register filename(ITLSEP247E12BFD0CD.tlv) event(1) session(0x7F7220283A60) callback
*Sep 18 15:39:38.395: PP: Data sent from 209.29.5.21/6970 to remote phone at 69.156.48.65/49713

*Sep 18 15:39:38.413: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.416: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.433: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.438: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.440: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.454: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.460: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.463: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.465: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.477: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.483: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.485: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:38.530: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:39:38.530: PP delete session:0x7F7220283A60, core:0, access:0
*Sep 18 15:39:38.530: DBG: unregister filename(ITLSEP247E12BFD0CD.tlv) event(3) session(0x7F7220283A60) callback
*Sep 18 15:39:38.530: Remove device hash table for phone 69.156.48.65 : 49713
*Sep 18 15:39:39.536: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:39:39.554: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:39:39.554: Phone proxy new phone event handler 1
*Sep 18 15:39:39.554: Phone proxy: TCP Socket accept
*Sep 18 15:39:39.555: Create device hash table for phone 69.156.48.65 : 49714
*Sep 18 15:39:39.555: TCP access socket inherit fd:0 from fd:5
*Sep 18 15:39:39.555: pp_add_tcp_access_socket session 0x7F7220283A60 access side raddr:69.156.48.65, socket:0

*Sep 18 15:39:39.557: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:39:39.557: access socket recv http:GET /SEP247E12BFD0CD.cnf.xml.sgn HTTP/1.1
Host:209.29.5.21:6970

*Sep 18 15:39:39.557: PP: Remote phone from 69.156.48.65/49714 requesting GET /SEP247E12BFD0CD.cnf.xml.sgn HTTP/1.1
Host:209.29.5.21:6970

at 209.29.5.21/6970

*Sep 18 15:39:39.557: get file name:SEP247E12BFD0CD.cnf.xml.sgn

*Sep 18 15:39:39.557: core side ip 10.26.200.11 session 0x7F7220283A60

*Sep 18 15:39:39.557: PP socket connect 1 remote addr 10.26.200.11 port 6970

*Sep 18 15:39:39.557: PP socket connect 1 remote addr 10.26.200.11 port 6970 in progress

*Sep 18 15:39:39.557: pp_add_tcp_core_socket session 0x7F7220283A60 core side raddr:10.26.200.11, socket:1
*Sep 18 15:39:39.557: PP: The remote phone is requesting file SEP247E12BFD0CD.cnf.xml.sgn.
PP: Removing .sgn extension, SBC is requesting file SEP247E12BFD0CD.cnf.xml.sgn from Call Manager HTTP server.

*Sep 18 15:39:39.557: PP: SBC sent request for SEP247E12BFD0CD.cnf.xml.sgn sourced from 10.26.200.30:40071 to 10.26.200.11:6970, vrf Global

*Sep 18 15:39:39.558: PP: modify http host, header:GET /SEP247E12BFD0CD.cnf.xml HTTP/1.1
Host:10.26.200.11:6970

, size: 65
*Sep 18 15:39:39.558: Phoneproxy tried to send data 0x7F72202D7340 65 bytes, socket 1 sent nothing,tcp connect not finished
*Sep 18 15:39:39.558: Got socket write event to resend on socket fd 1 resend queue:0x7F721D1FE4F0
*Sep 18 15:39:39.558: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:39:39.563: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:39:39.563: http core side first pkg
*Sep 18 15:39:39.564: http 200OK msg size:12997process http core side didn't finish,will continue process
*Sep 18 15:39:39.564: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60process http core side didn't finish,will continue process
*Sep 18 15:39:39.565: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60process http core side didn't finish,will continue process
*Sep 18 15:39:39.565: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60process http core side didn't finish,will continue process
*Sep 18 15:39:39.566: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60process http core side didn't finish,will continue process
*Sep 18 15:39:39.567: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:39:39.567: PP: Complete configuration file received from Call Manager TFTP server, beginning config file modification process.

*Sep 18 15:39:39.567: PP: Config Modify: rewriting addr to 10.26.200.11

*Sep 18 15:39:39.567: PP: Config Modify: rewriting addr to 0.0.0.0

*Sep 18 15:39:39.568: PP: CM Name Config Modify : detected Call Manager Name.
*Sep 18 15:39:39.568: PP: Config Modify: rewriting addr to 10.26.200.11

*Sep 18 15:39:39.568: PP: Config Modify: rewriting addr to 209.29.5.21

*Sep 18 15:39:39.568: PP: CM Name Config Modify : detected Call Manager Name.
*Sep 18 15:39:39.568: PP: Config Modify: rewriting port 5060 to 5060

*Sep 18 15:39:39.568: PP: Config Modify: rewriting port 5061 to 5061

*Sep 18 15:39:39.568: PP: Config Modify: rewriting addr to 10.26.200.11

*Sep 18 15:39:39.568: PP: Config Modify: rewriting addr to 209.29.5.21

*Sep 18 15:39:39.568: PP: CM Config Modify : detected Call Manager Node Name.
*Sep 18 15:39:39.568: PP: Config Modify: rewriting addr to 10.26.200.11

*Sep 18 15:39:39.568: PP: Config Modify: rewriting addr to 0.0.0.0

*Sep 18 15:39:39.568: PP: CM Name Config Modify : detected Call Manager Name.
*Sep 18 15:39:39.568: PP: Config Modify: rewriting port 5060 to 5060

*Sep 18 15:39:39.568: PP: Config Modify: rewriting port 5061 to 5061

*Sep 18 15:39:39.568: PP: Config Modify: rewriting addr to 10.26.200.11

*Sep 18 15:39:39.568: PP: Config Modify: rewriting addr to 0.0.0.0

*Sep 18 15:39:39.568: PP: Config Modify : detected Call Manager Node Name.
*Sep 18 15:39:39.569: PP: Config Modify : deviceSecurityMode set to 1 (unencrypted), modifying deviceSecurityMode to 3 (encrypted).

*Sep 18 15:39:39.569: PP: Url ipaddr invalid ip addr
*Sep 18 15:39:39.569: PP: Url ipaddr invalid ip addr
*Sep 18 15:39:39.569: PP: Url ipaddr invalid ip addr
*Sep 18 15:39:39.569: PP: Url ipaddr invalid ip addr
*Sep 18 15:39:39.569: PP: Url ipaddr invalid ip addr
*Sep 18 15:39:39.569: PP: Url ipaddr invalid ip addr
*Sep 18 15:39:39.569: PP: Url ipaddr invalid ip addr
*Sep 18 15:39:39.569: PP: Url ipaddr invalid ip addr
*Sep 18 15:39:39.569: PP: Config Modify : Modifying to TLS as the transport layer protocol.

*Sep 18 15:39:39.569: PP: Config Modify: rewriting addr to 0.0.0.0

*Sep 18 15:39:39.569: PP:CAPF Config Modify : detected Call Manager Node Name. Enter ctl_sign
PP: Encrypting and signing modified config file using trustpoint <selfsign>.
ctl_sign: total_file_len=13323, signature_len = 128

*Sep 18 15:39:39.575: PP: Data sent from 209.29.5.21/6970 to remote phone at 69.156.48.65/49714
process http core side succ,delete socket
*Sep 18 15:39:39.575: PP delete session:0x7F7220283A60, core:0, access:1
*Sep 18 15:39:39.595: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.597: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.615: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.619: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.621: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.636: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.642: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.644: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.646: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.658: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.664: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.666: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.668: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.670: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.672: Got socket write event to resend on socket fd 0 resend queue:0x7F721D1FE410
*Sep 18 15:39:39.725: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:39:39.725: PP delete session:0x7F7220283A60, core:0, access:0
*Sep 18 15:39:39.725: Remove device hash table for phone 69.156.48.65 : 49714
*Sep 18 15:39:42.356: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:39:42.375: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:39:42.375: Phone proxy new phone event handler 1
*Sep 18 15:39:42.375: Phone proxy: TCP Socket accept
*Sep 18 15:39:42.375: Create device hash table for phone 69.156.48.65 : 49715
*Sep 18 15:39:42.375: TCP access socket inherit fd:0 from fd:5
*Sep 18 15:39:42.375: pp_add_tcp_access_socket session 0x7F7220283A60 access side raddr:69.156.48.65, socket:0

*Sep 18 15:39:42.376: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:39:42.376: access socket recv http:GET /Canada/g3-tones.xml.sgn HTTP/1.1
Host:209.29.5.21:6970

*Sep 18 15:39:42.376: PP: Remote phone from 69.156.48.65/49715 requesting GET /Canada/g3-tones.xml.sgn HTTP/1.1
Host:209.29.5.21:6970

at 209.29.5.21/6970

*Sep 18 15:39:42.377: get file name:Canada/g3-tones.xml.sgn

*Sep 18 15:39:42.377: DBG: check if filename(Canada/g3-tones.xml.sgn) buffered
*Sep 18 15:39:42.377: core side ip 10.26.200.11 session 0x7F7220283A60

*Sep 18 15:39:42.377: PP socket connect 1 remote addr 10.26.200.11 port 6970

*Sep 18 15:39:42.377: PP socket connect 1 remote addr 10.26.200.11 port 6970 in progress

*Sep 18 15:39:42.377: pp_add_tcp_core_socket session 0x7F7220283A60 core side raddr:10.26.200.11, socket:1
*Sep 18 15:39:42.377: PP: SBC sent request for Canada/g3-tones.xml.sgn sourced from 10.26.200.30:40072 to 10.26.200.11:6970, vrf Global

*Sep 18 15:39:42.377: PP: modify http host, header:GET /Canada/g3-tones.xml.sgn HTTP/1.1
Host:10.26.200.11:6970

, size: 65
*Sep 18 15:39:42.377: Phoneproxy tried to send data 0x7F72202D7340 65 bytes, socket 1 sent nothing,tcp connect not finished
*Sep 18 15:39:42.378: Got socket write event to resend on socket fd 1 resend queue:0x7F721D1FE4F0
*Sep 18 15:39:42.378: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:39:42.380: PP: pp_sock_tcp_read_handler sock:1 session:7F7220283A60
*Sep 18 15:39:42.380: http core side first pkg
*Sep 18 15:39:42.380: http error msg
*Sep 18 15:39:42.380: PP: Data sent from 209.29.5.21/6970 to remote phone at 69.156.48.65/49715
process http core side succ,delete socket
*Sep 18 15:39:42.380: PP delete session:0x7F7220283A60, core:0, access:1
*Sep 18 15:39:42.400: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:39:42.400: PP delete session:0x7F7220283A60, core:0, access:0
*Sep 18 15:39:42.400: Remove device hash table for phone 69.156.48.65 : 49715
*Sep 18 15:39:42.786: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:39:42.804: Phoneproxy_mgt_process, unknown event.

*Sep 18 15:39:42.804: Phone proxy new phone event handler 1
*Sep 18 15:39:42.804: Phone proxy: TCP Socket accept
*Sep 18 15:39:42.805: Create device hash table for phone 69.156.48.65 : 49716
*Sep 18 15:39:42.805: TCP access socket inherit fd:0 from fd:5
*Sep 18 15:39:42.805: pp_add_tcp_access_socket session 0x7F7220283A60 access side raddr:69.156.48.65, socket:0

*Sep 18 15:39:42.805: PP: pp_sock_tcp_read_handler sock:0 session:7F7220283A60
*Sep 18 15:39:42.806: access socket recv http:GET /AppDialRules.xml HTTP/1.1
Host:209.29.5.21:6970

jtwardowski · ‎09-18-2018

one more clarification - config was also changed for posting purpose (IP replaces with <device_ip> statements.)