ASA Phone Proxy Troubleshooting and Common Problems

Jay Johnston · ‎06-10-2009

Purpose
Description
Documentation
Licensing
Phone Configuration and Tasks
Troubleshooting / Debugging
Common Problems
Show Commands with Sample Output
Syslogs
Debugs with Sample Output

Purpose

The Cisco adaptive security appliance phone proxy is the replacement product for the Cisco Unified Phone Proxy. This page is intended to assist with troubleshooting problems with Phone Proxy feature on the firewall

Description

The Cisco ASA phone proxy feature allows for phones to establish secured communication channels directly with the ASA; These secure communications terminate directly onto the firewall, and the firewall "proxies" the voice communication between the phone and the Call Manager.

This feature allows for secure voice communication for phones deployed in the field without requiring a separate device to encrypt the traffic to the call manager.

Documentation

ASA 8.0 Configuration guide - Phone Proxy feature

ASA Phone Proxy sample configuration in 8.0

Official Phone Proxy troubleshooting Documentation

Licensing

To determine the number of remote phones can connect to the phone-proxy, use the "show version" command. Note the line that reads "UC Proxy Sessions":

PhoneProxyASA#show version

Cisco Adaptive Security Appliance Software Version 8.0(4) 
Device Manager Version 5.2(4)
....
UC Proxy Sessions            : 2

This is the total number of TLS proxy sessions that can be simultaneously established. For instance, if there is only one CUCM in the cluster, then the total number of phones that can be registered through the phone-proxy is 2. If there is a backup and a primary CUCM in the cluster, then only 1 phone can be registered since the phone would also initiate a TLS connection to the backup CUCM and consume a TLS connection. For more information on licensing, please seehttp://www.cisco.com/en/US/docs/security/asa/asa80/configuration/guide/unified_comm.html#wp1139894.

To see what phones are connected use the command "show tls-proxy session". If the license becomes exceeded, you will receive the syslog below:

%ASA-4-446002: Denied TLS Proxy session from outside:10.10.10.2/49572 to 
inside:192.168.1.2/2000, licensed UC Proxy session limit of 20 exceeded

Please note that if users disconnect and then re-connect quickly from a different ip address, the firewall might be affected by the bug CSCsu11361.

Phone Configuration and Tasks

Setting the tftp-server

To set the TFTP server on the phone, do the following

Press the "Settings" button
Choose "3 - Network Configuration"
Press "* * #" to unlock the phone. You will see the lock icon in the upper right of the phone change to an unlocked symbol.
Ensure that option "24 Alternate TFTP" (on older phones it might be option 32) is set to "YES"
Set the correct TFTP server address under option "8 TFTP Server 1"

Deleting the CTL file on the phone

Press the "Settings" button
Choose "Security Configuration" (might be option 4 or 6, depending upon phone model)
Unlock the phone with "* * #"
Scroll down to "CTL file" and press "Select"
Press the "Erase" button (might have to press "more" first)

Viewing the status messages on the phone

Press the "Settings" button
Scroll down to "Status" and press "Select"
Press "Select" on the first option: "Status Messages"

Troubleshooting / Debugging

Step-by-step walkthrough of phone registration process

This is a step by step walkthrough of what occurs when the phone connects to the phone-proxy.

The phone powers on and attempts to obtain an ip address via DHCP
If the phone has no CTL file present, it attempts to download one from the tftp server
- When the phone sends the tftp request for the CTL file, the ASA will send it's own CTL file that was generated on the firewall. Therefore, no packets are actually sent or forwarded to the inside Call Manager; they are all "spoofed" by the ASA.
- If the phone has an "old" CTL File that was downloaded from a different Call Manager, the next step might fail if the new CTL file was not signed by the SAST keys from the "old" CTL file. So if the new CTL file was signed by a different SAST keys, the phone will reject it with an error stating "CTL File Not Authorized". The old CTL file should be cleared so that the new correct CTL file can be downloaded.
The phone then reads the tftp server entry in its configuration, and sends a request for the file "SEPxxxxxxxxxxx.cfg.xml" where the x's represent the MAC address of the phone
The ASA intercepts this tftp request and pulls down the config file from the Call Manager to it's own memory. It then modifies the config file before sending the modified file on to the phone. During this process, the tftp packets sent to the Call Manager from the ASA will have a source IP address of the phone, not the inside interface of the firewall; this is important because the return traffic sent from the Call Manager back to the phone must traverse to the ASA. Once the file has been obtained, the ASA makes the following changes to it before sending it over to the phone
- It looks for the "securityDeviceMode" entry and sets this to "3" to be Encrypted.
- It changes other phone security parameters as per the settings on the ASA. See the command "no disable service-settings" under the phone-proxy instance configuration.
- It performs NAT on the CUCM's IP address and CAPF address if present.
- It rewrites the proxyServerURL if it is configured.
- It creates an ACL to allow the phone to initiate a TLS connection to the CUCM.
- It creates an app-redirect rule from the phone to the CUCM if the phone is configured as a nonsecure phone on the CUCM.
The phone receives the modified configuration file, and attempts to make a new secure TCP connection to the Call Manager's global ip address (as configured in the translation on the firewall). In the case of SCCP (Skinny) this connection will be made on TCP port 2443 and in the case of SIP it will be 5061.
- At this point it is important to note that the when the traffic from the phone reaches the call manager, the source IP address will be that of the phone. Therefore, it is important that the return traffic from the callmanager back to the phone flow through the ASA. If it does not, the registration will fail.
During the TLS handshake, TLS proxy will extract the phone's MAC address from the certificate that the phone presented and checks to see if this MAC address from the phone's IP address is present in the phone-proxy's secure-phone DB. The contents of the secure-phone DB can be seen via the command "show phone-proxy secure-phones". If the phone has an entry in the secure-phone DB, then the TLS handshake will proceed, otherwise, the TLS proxy will reject it and the phone will not be able to register.
An unecrypted skinny connection is made by the ASA to the call manager for each phone connected IF the phone is configured as a nonsecure phone. If it was configured as an Encrypted phone with a secure profile, then the connection between the ASA to the CUCM would be encrypted as well. An encrypted connection is established between the ASA and each phone connected.
The remote secure phone then starts sending SRTP to the ASA's media-termination address. The ASA will then decrypt the SRTP packet and send it out as an RTP packet if the other leg to the other phone is nonsecure. Likewise, the receiving phone will send SRTP or RTP to the ASA's media-termination and the ASA will encrypt/re-encrypt the packet and send it out as SRTP to the remote secure phone.

Common Problems

Phone registration problems

Cisco manufacturing certificates not loaded into the ASA

If the Cisco CA manufacturing certificates have not been installed on the ASA, and the phone connecting in is using a MIC (and not a LSC cert), then you'll see the following syslogs:

Aug 29 2008 09:03:30: %ASA-6-725001: Starting SSL handshake with client 
outside:192.168.254.254/50272 for TLSv1 session.
Aug 29 2008 09:03:30: %ASA-7-725010: Device supports the following 4 cipher(s).
Aug 29 2008 09:03:30: %ASA-7-725011: Cipher[1] : RC4-SHA
Aug 29 2008 09:03:30: %ASA-7-725011: Cipher[2] : AES128-SHA
Aug 29 2008 09:03:30: %ASA-7-725011: Cipher[3] : AES256-SHA
Aug 29 2008 09:03:30: %ASA-7-725011: Cipher[4] : DES-CBC3-SHA
Aug 29 2008 09:03:30: %ASA-7-725008: SSL client outside:192.168.254.254/50272 proposes the 
following 2 cipher(s).
Aug 29 2008 09:03:30: %ASA-7-725011: Cipher[1] : AES256-SHA
Aug 29 2008 09:03:30: %ASA-7-725011: Cipher[2] : AES128-SHA
Aug 29 2008 09:03:30: %ASA-7-725012: Device chooses cipher : AES128-SHA for the SSL 
session with client outside:192.168.254.254/50272
Aug 29 2008 09:03:32: %ASA-7-725014: SSL lib error. Function: SSL3_READ_BYTES Reason: ssl 
handshake failure
Aug 29 2008 09:03:32: %ASA-7-717025: Validating certificate chain containing 1 
certificate(s).
Aug 29 2008 09:03:32: %ASA-7-717029: Identified client certificate within certificate 
chain. serial number: 19567F78000000281D45, subject name:
cn=CP-7942G-SEP001DA23EA450,ou=EVVBU,o=Cisco Systems Inc..
Aug 29 2008 09:03:32: %ASA-3-717009: Certificate validation failed. No suitable 
trustpoints found to validate certificate serial number: 19567F78000000281D45, subject 
name: cn=CP-7942G-SEP001DA23EA450,ou=EVVBU,o=Cisco Systems Inc..
Aug 29 2008 09:03:32: %ASA-3-717027: Certificate chain failed validation. No suitable 
trustpoint was found to validate chain.
Aug 29 2008 09:03:32: %ASA-7-725014: SSL lib error. Function: SSL3_GET_CLIENT_CERTIFICATE 
Reason: no certificate returned
Aug 29 2008 09:03:32: %ASA-6-725006: Device failed SSL handshake with outside 
client:192.168.254.254/50272
Aug 29 2008 09:03:32: %ASA-6-302014: Teardown TCP connection 797 for 
outside:192.168.254.254/50272 to inside:10.55.151.140/2000 duration 0:00:01 bytes 623 Flow 
closed by inspection

Phone does not have a certificate installed

Symptom: The phone will download the TFTP configuration but will then fail to connect to the firewall on port the secure port 2443. Instead it connects on port non-secure port 2000 (the non-secure port). If the phone has no certificate installed, then it will ignore the config file entry that says to use encryption and will connect as if it were non-secure. If the outside ACL allows inbound connections on port 2000, the phone might register with the Call Manager, but in non-secure mode. If inbound port 2000 is blocked, the phone will fail to register and simply read "Opening x.x.x.x". The status messages on the phone will just show that the config file was downloaded, and that's it. The tftp debugs will show the CTL and configuration file are downloaded successfully

PP: 172.18.254.73/51783 requesting CTLSEP0007EBF0EE54.tlv
PP: Created entry for secure device outside:172.18.254.73, MAC 0007.ebf0.ee54, current count 1, list count 3
PP: opened 0x32b3cfea
PP: Data Block 1 forwarded from 14.36.107.90/46309 to 172.18.254.73/51783 ingress ifc outside
PP: Received ACK Block 1 from outside:172.18.254.73/51783 to inside:172.18.124.230
PP: Data Block 2 forwarded to 172.18.254.73/51783
PP: Received ACK Block 2 from outside:172.18.254.73/51783 to inside:172.18.124.230
PP: Data Block 3 forwarded to 172.18.254.73/51783
PP: Received ACK Block 3 from outside:172.18.254.73/51783 to inside:172.18.124.230
PP: Data Block 4 forwarded to 172.18.254.73/51783
PP: Received ACK Block 4 from outside:172.18.254.73/51783 to inside:172.18.124.230
PP: Data Block 5 forwarded to 172.18.254.73/51783
PP: Received ACK Block 5 from outside:172.18.254.73/51783 to inside:172.18.124.230
PP: Data Block 6 forwarded to 172.18.254.73/51783
PP: Received ACK Block 6 from outside:172.18.254.73/51783 to inside:172.18.124.230
PP: Data Block 7 forwarded to 172.18.254.73/51783
PP: Received ACK Block 7 from outside:172.18.254.73/51783 to inside:172.18.124.230
PP: Data Block 8 forwarded to 172.18.254.73/51783
PP: Received ACK Block 8 from outside:172.18.254.73/51783 to inside:172.18.124.230
PP: Data Block 9 forwarded to 172.18.254.73/51783
PP: Received ACK Block 9 from outside:172.18.254.73/51783 to inside:172.18.124.230
PP: TFTP session complete, all data sent
PP: 172.18.254.73/51784 requesting SEP0007EBF0EE54.cnf.xml.sgn
PP: opened 0x32b48326
PP: Received Data Block 1 from inside:172.18.124.230/32815 to outside:172.18.254.73/51784
        Received Block 1
PP: Acked Block #1 from 172.18.124.241/33423 to 172.18.124.230/32815
PP: Received Data Block 2 from inside:172.18.124.230/32815 to outside:172.18.254.73/51784
        Received Block 2
PP: Acked Block #2 from 172.18.124.241/33423 to 172.18.124.230/32815
PP: Received Data Block 3 from inside:172.18.124.230/32815 to outside:172.18.254.73/51784
        Received Block 3
PP: Acked Block #3 from 172.18.124.241/33423 to 172.18.124.230/32815
PP: Received Data Block 4 from inside:172.18.124.230/32815 to outside:172.18.254.73/51784
        Received Block 4
PP: Acked Block #4 from 172.18.124.241/33423 to 172.18.124.230/32815
PP: Received Data Block 5 from inside:172.18.124.230/32815 to outside:172.18.254.73/51784
        Received Block 5
PP: Acked Block #5 from 172.18.124.241/33423 to 172.18.124.230/32815
PP: Received Data Block 6 from inside:172.18.124.230/32815 to outside:172.18.254.73/51784
        Received Block 6
PP: Acked Block #6 from 172.18.124.241/33423 to 172.18.124.230/32815
PP: Received Data Block 7 from inside:172.18.124.230/32815 to outside:172.18.254.73/51784
        Received Block 7
PP: Acked Block #7 from 172.18.124.241/33423 to 172.18.124.230/32815
PP: Received Data Block 8 from inside:172.18.124.230/32815 to outside:172.18.254.73/51784
        Received Block 8
PP: Acked Block #8 from 172.18.124.241/33423 to 172.18.124.230/32815
PP: Added ACL for 172.18.254.73 to outside:14.36.107.90/2443
PP: Applied Application Redirect rule for 172.18.254.73/2000 to 14.36.107.90, secure port 2443
PP: Added ACL for 172.18.254.73 to outside:14.36.107.90/59699
PP: Applied Application Redirect rule for 172.18.254.73/3804 to 14.36.107.90, secure port 59699
PP: Modifying to encrypted mode.
PP: Modifying to TLS as the transport layer protocol.
PP: Data Block 1 forwarded from 14.36.107.90/9694 to 172.18.254.73/51784
PP: Received ACK Block 1 from outside:172.18.254.73/51784 to inside:172.18.124.230
PP: Data Block 2 forwarded to 172.18.254.73/51784
PP: Received ACK Block 2 from outside:172.18.254.73/51784 to inside:172.18.124.230
PP: Data Block 3 forwarded to 172.18.254.73/51784
PP: Received ACK Block 3 from outside:172.18.254.73/51784 to inside:172.18.124.230
PP: Data Block 4 forwarded to 172.18.254.73/51784
PP: Received ACK Block 4 from outside:172.18.254.73/51784 to inside:172.18.124.230
PP: Data Block 5 forwarded to 172.18.254.73/51784
PP: Received ACK Block 5 from outside:172.18.254.73/51784 to inside:172.18.124.230
PP: Data Block 6 forwarded to 172.18.254.73/51784
PP: Received ACK Block 6 from outside:172.18.254.73/51784 to inside:172.18.124.230
PP: Data Block 7 forwarded to 172.18.254.73/51784
PP: Received ACK Block 7 from outside:172.18.254.73/51784 to inside:172.18.124.230
PP: Data Block 8 forwarded to 172.18.254.73/51784
PP: Received ACK Block 8 from outside:172.18.254.73/51784 to inside:172.18.124.230
PP: TFTP session complete, all data sent

The syslogs simply show the tftp connections, and then the subsequent skinny connection on port 2000.

Sep 19 2008 15:19:03: %ASA-7-609001: Built local-host outside:172.18.254.73
Sep 19 2008 15:19:03: %ASA-6-305011: Built dynamic UDP translation from 
outside:172.18.254.73/51783 to inside:172.18.124.241/41910
Sep 19 2008 15:19:03: %ASA-6-302015: Built inbound UDP connection 25958 for 
outside:172.18.254.73/51783 (172.18.124.241/41910) to inside:172.18.124.230/69 (14.36.107.90/69)
Sep 19 2008 15:19:03: %ASA-6-305011: Built dynamic UDP translation from 
inside:172.18.124.230/39638 to outside:14.36.107.90/46309
Sep 19 2008 15:19:03: %ASA-6-302015: Built inbound UDP connection 25959 for 
outside:172.18.254.73/51783 (172.18.124.241/41910) to inside:172.18.124.230/39638 (14.36.107.90/46309)
Sep 19 2008 15:19:04: %ASA-6-305012: Teardown dynamic UDP translation from 
inside:172.18.124.230/32813 to outside:14.36.107.90/62674 duration 0:02:30
Sep 19 2008 15:19:05: %ASA-6-305011: Built dynamic UDP translation from 
outside:172.18.254.73/51784 to inside:172.18.124.241/33423
Sep 19 2008 15:19:05: %ASA-6-302015: Built inbound UDP connection 25960 for 
outside:172.18.254.73/51784 (172.18.124.241/33423) to inside:172.18.124.230/69 (14.36.107.90/69)
Sep 19 2008 15:19:05: %ASA-6-302015: Built inbound UDP connection 25961 for 
outside:172.18.254.73/51784 (172.18.124.241/33423) to inside:172.18.124.230/32815 (14.36.107.90/9694)
Sep 19 2008 15:19:05: %ASA-6-305011: Built dynamic TCP translation from 
inside:172.18.124.230/3804 to outside:14.36.107.90/59699
Sep 19 2008 15:19:06: %ASA-2-106001: Inbound TCP connection denied from 
172.18.254.73/51989 to 14.36.107.90/2000 flags SYN  on interface outside
Sep 19 2008 15:19:07: %ASA-2-106001: Inbound TCP connection denied from 
172.18.254.73/51989 to 14.36.107.90/2000 flags SYN  on interface outside

Traffic from Call Manager to phone does not traverse ASA causing TFTP failures

The traffic from the Call Manager back to the phone must traverse the ASA; if it does not, the registration process will fail due to the asymmetric routing.

In this situation, the CTL file will be downloaded by the phone just fine, since it is receiving this directly from the ASA (and the Call Manager is not involved yet). Once the phone has the CTL file, it will send a TFTP request to the Call Manager; this tftp request packet will be sourced from the phone's real external IP. The Call Manager will respond by sending the requested tftp data destined back to the phone's real ip address. The network must route the return packets from the Call Manager back to the phones through the firewall. If the packets do not traverse the ASA, when they are received at the phone they will be dropped. Depending on where the ASA is placed on the network, fixing this routing problem could require some additional (possibly major) routing changes. One workaround is to perform inbound NAT/PAT on all the phone traffic as it enters the network, but this might cause other problems (especially if nat-control is enabled. If nat-control is enabled and any outside NAT/PAT is configured, then outside NAT will have to be configured for all inbound traffic).

Here is a picture showing the problem:

Here is an example of the output of 'debug phone-proxy tftp' when a remote phone connecting to the phone proxy on the ASA. The network is not routing the traffic from the Call Manager to the phone through the ASA, and thus the TFTP transfer of the configuration file fails. The phone will retry the download over and over.

PP: 172.18.254.73/52361 requesting CTLSEP0007EBF0EE54.tlv
PP: opened 0x116804ea
PP: Data Block 1 forwarded from 14.36.107.90/8554 to 172.18.254.73/52361 ingress ifc outside
PP: Received ACK Block 1 from outside:172.18.254.73/52361 to inside:172.18.124.230
PP: Data Block 2 forwarded to 172.18.254.73/52361
PP: Received ACK Block 2 from outside:172.18.254.73/52361 to inside:172.18.124.230
PP: Data Block 3 forwarded to 172.18.254.73/52361
PP: Received ACK Block 3 from outside:172.18.254.73/52361 to inside:172.18.124.230
PP: Data Block 4 forwarded to 172.18.254.73/52361
PP: Received ACK Block 4 from outside:172.18.254.73/52361 to inside:172.18.124.230
PP: Data Block 5 forwarded to 172.18.254.73/52361
PP: Received ACK Block 5 from outside:172.18.254.73/52361 to inside:172.18.124.230
PP: Data Block 6 forwarded to 172.18.254.73/52361
PP: Received ACK Block 6 from outside:172.18.254.73/52361 to inside:172.18.124.230
PP: Data Block 7 forwarded to 172.18.254.73/52361
PP: Received ACK Block 7 from outside:172.18.254.73/52361 to inside:172.18.124.230
PP: Data Block 8 forwarded to 172.18.254.73/52361
PP: Received ACK Block 8 from outside:172.18.254.73/52361 to inside:172.18.124.230
PP: Data Block 9 forwarded to 172.18.254.73/52361
PP: Received ACK Block 9 from outside:172.18.254.73/52361 to inside:172.18.124.230
PP: TFTP session complete, all data sent
PP: 172.18.254.73/52362 requesting SEP0007EBF0EE54.cnf.xml.sgn
PP: opened 0x116974f6
PP: 172.18.254.73/52363 requesting SEP0007EBF0EE54.cnf.xml.sgn
PP: opened 0x116a21e2
PP: 172.18.254.73/52364 requesting SEP0007EBF0EE54.cnf.xml.sgn
PP: opened 0x116b06ae

The phone will continue to request the config file, but will never be successful. Adding outside PAT for this remote phone will mitigate the problem (in this case I've performed PAT on all outside traffic going inbound through the firewall):

PhoneProxyASA(config)# nat (outside) 55 0 0 outside
PhoneProxyASA(config)# global (inside) 55 interface

or

Here is a sample which does PAT outside for only traffic destined to the call manager on the inside.

PhoneProxyASA(config)#object-group service CUCM-PROXY-PORTS 
PhoneProxyASA(config-service)#service-object udp eq tftp 
                              service-object udp range 1024 65535 
                              service-object tcp eq 2443 
                              service-object tcp eq 5061 
                              service-object tcp eq 3804
 
PhoneProxyASA(config)#access-list cucm-traffic extended permit object-group 
CUCM-PROXY-PORTS any host 172.18.124.230 

PhoneProxyASA(config)#nat (outside) 55 access-list cucm-traffic outside
PhoneProxyASA(config)#global (inside) 55 interface

Where 172.18.124.230 is the translated address of the call manager on the inside.

or

PhoneProxyASA(config)# nat (outside) 55 172.18.254.73 255.255.255.255 outside
PhoneProxyASA(config)# global (inside) 55 interface

where 172.18.254.73 is the ip address of the phone on the outside.

or

Under 8.3, NAT configuration format has changed. Twice NAT is introduced for policy based NAT. Below is a working Twice NAT that dynamically PAT any traffic destined to the CUCM public ip address translating the source to the ASA's inside ip address and the destination from the CUCM public ip address to its corresponding private ip address.

PhoneProxyASA(config)# object network obj-cucm-public
PhoneProxyASA(config-network-object)# host <cucm-public-ip-address>

PhoneProxyASA(config)# object network obj-cucm-private
PhoneProxyASA(config-network-object)# host <cucm-private-ip-address>

PhoneProxyASA(config)# nat (outside,inside) source dynamic any interface destination static obj-cucm-public obj-cucm-private

Call Manager cluster has multiple devices, ASA only configured for one

If the Call Manager cluster has multiple devices (TFTP server, Publisher, Subscriber etc) then there will need to be static translations, ctl-file entries and trustpoints for each individual device.

DNS resolution problems on the ASA

If the call manager is defined by its hostname (not by ip address) then when the phone first pulls the tftp configuration down the ASA will try to perform a lookup on the call manager hostname and this will fail. You'll see the following in the output of "debug phone-proxy tftp"

....
PP: Received Data Block 15 from vlan100:172.16.100.1/34248 to vlan96:172.16.96.16/49165
       Received Block 15
PP: Acked Block #15 from 172.16.96.16/49165 to 172.16.100.1/34248
PP: Received Data Block 16 from vlan100:172.16.100.1/34248 to vlan96:172.16.96.16/49165
       Received Block 16
PP: Acked Block #16 from 172.16.96.16/49165 to 172.16.100.1/34248
PP: Received Data Block 17 from vlan100:172.16.100.1/34248 to vlan96:172.16.96.16/49165
       Received Block 17
PP: Acked Block #17 from 172.16.96.16/49165 to 172.16.100.1/34248
PP: Received Data Block 18 from vlan100:172.16.100.1/34248 to vlan96:172.16.96.16/49165
       Received Block 18
PP: Acked Block #18 from 172.16.96.16/49165 to 172.16.100.1/34248
PP: Unable to get dns response for id 7
PP: Callback, error modifying config file
PP: Unable to CM name addr
PP: Callback required for parsing config file

The solution is to configure name resolution on the ASA, so it can resolve the ip for the name of the call manager

Time incorrect on ASA, causing certificate validation failures

The certificate offered by the phone might be rejected if the date is wrong on the firewall. The phone might flash an error referring to TLS problems.

The syslogs on the firewall will show the following:

Jan 02 2005 22:22:38: %ASA-6-305011: Built dynamic TCP translation from 
outside:172.18.254.95/1072 to inside:172.18.124.241/3165
Jan 02 2005 22:22:38: %ASA-6-302013: Built inbound TCP connection 569 for 
outside:172.18.254.95/1072 (172.18.124.241/3165) to inside:172.18.124.230/2000 (14.36.107.90/2443)
Jan 02 2005 22:22:38: %ASA-6-725001: Starting SSL handshake with client 
outside:172.18.254.95/1072 for TLSv1 session.
Jan 02 2005 22:22:38: %ASA-7-725010: Device supports the following 4 cipher(s).
Jan 02 2005 22:22:38: %ASA-7-725011: Cipher[1] : RC4-SHA
Jan 02 2005 22:22:38: %ASA-7-725011: Cipher[2] : AES128-SHA
Jan 02 2005 22:22:38: %ASA-7-725011: Cipher[3] : AES256-SHA
Jan 02 2005 22:22:38: %ASA-7-725011: Cipher[4] : DES-CBC3-SHA
Jan 02 2005 22:22:38: %ASA-7-725008: SSL client outside:172.18.254.95/1072 proposes 
the following 2 cipher(s).
Jan 02 2005 22:22:38: %ASA-7-725011: Cipher[1] : AES256-SHA
Jan 02 2005 22:22:38: %ASA-7-725011: Cipher[2] : AES128-SHA
Jan 02 2005 22:22:38: %ASA-7-725012: Device chooses cipher : AES128-SHA for the SSL 
session with client outside:172.18.254.95/1072
Jan 02 2005 22:22:38: %ASA-7-111009: User 'enable_15' executed cmd: show logging
Jan 02 2005 22:22:40: %ASA-7-717025: Validating certificate chain containing 1 
certificate(s).
Jan 02 2005 22:22:40: %ASA-7-717029: Identified client certificate within certificate 
chain. serial number: 01, subject name: cn=SEP0007EBF0EE54.
Jan 02 2005 22:22:40: %ASA-7-717030: Found a suitable trustpoint capf_trustpoint to 
validate certificate.
Jan 02 2005 22:22:40: %ASA-3-717009: Certificate validation failed. Certificate date 
is out-of-range, serial number: 01, subject name: cn=SEP0007EBF0EE54.
Jan 02 2005 22:22:40: %ASA-3-717027: Certificate chain failed validation. Certificate 
chain date is out-of-range.
Jan 02 2005 22:22:40: %ASA-7-725014: SSL lib error. Function: SSL3_GET_CLIENT_CERTIFICATE 
Reason: no certificate returned
Jan 02 2005 22:22:40: %ASA-6-725006: Device failed SSL handshake with outside 
client:172.18.254.95/1072
Jan 02 2005 22:22:40: %ASA-6-302014: Teardown TCP connection 569 for 
outside:172.18.254.95/1072 to inside:172.18.124.230/2000 duration 0:00:02 bytes 901 Flow closed by inspection

Phone call-audio problems

Popping sound heard during calls

Please see bug id CSCsv86408.

One way, or no-way voice audio when call established

* Please note that starting in ASA version 8.2, a Media Termination Address can be configured on a per-interface basis. This resolves many of the call audio-routing problems that some administrators encountered when deploying phone-proxy in version 8.0. For more information on per-interface MTA, see the config example here: https://supportforums.cisco.com/docs/DOC-8165

http://www.cisco.com/en/US/docs/security/asa/asa83/configuration/guide/unified_comm_phoneproxy.html#wp1236241

The most likely cause of this problem is incorrect packet routing, caused by one of the following situations:

Packets sent from the phone destined to the MTA address do not reach the firewall at all. A capture taken on the firewall (on each interface of the firewall) of all traffic sent to and from the MTA would show if this is the case. If the packets aren't reaching the firewall then further troubleshooting is needed to determine where they are dropped.
Packets sent from the phone destined to the MTA address do reach the firewall and arrive on interface X, but the traffic sent from the ASA to the phone was sent out interface Y. A capture taken on the firewall (on each interface of the firewall) of all traffic sent to and from the MTA would show if this is the case. If the voice traffic received from a phone enters the firewall on a different interface than which the firewall sent voice traffic to that phone, the packets will be dropped by the ASA. The reason for this is that the UDP packets received from the phone won't match the connection that was built by the firewall. You'll see ASP drops due to 'no matching conn'.

An example of this is shown here:

Please note that starting in the upcoming version 8.2, a new feature is being added that supports per-interface Media Termination Addresses. This will mitigate the problem outlined in this example.

You can potentially mitigate this problem by doing one of the following:

Adding static routes on the inside of the network so that traffic destined to the MTA is routed to the inside interface of the firewall
Adding a static route on an adjacent device, and redistributing this route throughout the routing protocol running on the inside
Changing the routing table of the firewall such that the audio traffic is sent out the interface on which it is received. In the example above, you would add a route on the firewall so that traffic destined to 10.99.22.3 is sent out the outside interface.

Phone Services problems

Directory Serves and Authentication services not working with Call Manager 8.0 installations

As part of Call Manager 8.0 (CUCM 8.0) phone HTTP services, such as directory and authentication, will now use HTTPS connections by default. At this time, these features are not supported with the proxy-server functionality of the ASA's Phone Proxy.

Please see ASA defect CSCti62447

Why it does not work

In order for the Phones to make secure (HTTPS) connections, the phone must now communicate with the TVS store on the Call Manager. Currently, Phone Proxy does not support communication with the TVS store and as a result, Secure Services will fail.

The message flow for TVS without Phone Proxy will be the following:

Phone downloads ITL (Identity Trust List) file from CUCM server when the phone boots. The ITL is a list of Trust Verification Servers and their certs.
Phone starts SSL handshake to HTTPS server for the desired service (e.g. Directories)
HTTPS Server sends back Server Hello and Server Certificate to Phone.
Phone creates an SSL connection to one of the TVS servers on TCP port 2445. The TVS servers are just CUCM servers.
Phone asks the TVS server "Is this server certificate in the CUCM trust store, or signed by a certificate in the CUCM trust store?"
If yes, the SSL handshake to the original HTTPS Server continues. If not, the SSL handshake fails.

This feature allows us to maintain one trust store on the CUCM server for all IP Phone endpoints that support TVS. This will be enabled by default on all 3rd gen and newer phones running 9.X phone firmware on 8.X CUCM.

Workaround
In order to get this to work with the current Phone Proxy implementation, you need to force the phone to use HTTP instead of HTTPS. There is no straight forward way of achieving this. In order to have the phone use HTTP instead of HTTPS please configure the following setting in Call Manager for the remote phone-proxy phone

Manually specify the non HTTPS versions of the different Phone Service URLs in the phones configuration in Call Manager (CCMAdmin > Device > Phone). Make sure to fill both the normal and 'secured' fields with the HTTP URL lines

Ensure the phone is set for 'External' or 'Both' under Services Provisioning in Call Manager (CCMAdmin > Device > Phone). This will allow it to use the URLs we will provide.

Once the phone configuration on the Call Manager is set correctly, configure the 'proxy-server' functionality in the ASA phone-proxy config as you would normally. For example:

phone-proxy ASA-phone-proxy
media-termination phone-proxy-mta
tftp-server address 192.168.0.11 interface Inside

tls-proxy ASA-tls-proxy
ctl-file ctl_phoneproxy_file
proxy-server address 192.168.0.11 interface Inside

Show Commands with Sample Output

These show commands are taken in the context of the following network diagram:

show phone-proxy secure-phones

This shows all phones currently in the phone-proxy's secure-phone DB. Note that if the Port for a phone is 0, that means the phone has not successfully registered with the CUCM.

PhoneProxyASA# show phone-proxy secure-phones 
ASA-phone-proxy: 2 in use, 2 most used  

           Interface      IP Address  Port MAC            Timeout Idle 
             outside   172.18.254.25 19931 0009.b7d0.eea7 0:05:00 0:00:11 
             outside   172.18.254.73 50124 0007.ebf0.ee54 0:05:00 0:00:08 
PhoneProxyASA#

show phone-proxy media-sessions

This shows all currently active media-sessions (calls) that are flowing through the firewall. If no calls are currently up, this output will be blank.

PhoneProxyASA# show phone-proxy media-sessions 
2 in use, 2 most used
Media-session: 14.36.107.91/26830 :: client ip 172.18.254.73/29836
  Lcl SRTP conn 14.36.107.91/26830 to 172.18.254.25/41282 tx_pkts 60 rx_pkts 61

Media-session: 14.36.107.91/29724 :: client ip 172.18.254.25/41282
  Lcl SRTP conn 14.36.107.91/29724 to 172.18.254.73/29836 tx_pkts 61 rx_pkts 61

PhoneProxyASA#

show tls-proxy sessions

This shows all the phones currently terminating TLS connections on the ASA.

PhoneProxyASA# show tls-proxy sessions 
3 in use (3 established), 7 most used
outside 172.18.254.95:1035 inside 172.18.124.230:2000 P:0xd5a407f0(ASA-tls-proxy) S:0xd5bd4738 byte 8392
outside 172.18.254.46:1143 inside 172.18.124.230:2000 P:0xd5a407f0(ASA-tls-proxy) S:0xd5bd7c90 byte 8572
outside 172.18.254.49:6136 inside 172.18.124.230:2000 P:0xd5a407f0(ASA-tls-proxy) S:0xd5bbac40 byte 6460

You will see an identical connection in the show conn output:

PhoneProxyASA# show conn
4 in use, 48 most used
TCP outside 172.18.124.241(172.18.254.95):1035 inside 172.18.124.230:2000, idle 0:00:27, bytes 16951, flags UIOB
TCP outside 172.18.124.241(172.18.254.49):6136 inside 172.18.124.230:2000, idle 0:00:13, bytes 13949, flags UIOB
TCP outside 172.18.124.241(172.18.254.46):1143 inside 172.18.124.230:2000, idle 0:00:04, bytes 17213, flags UIOB

show tls-proxy sessions detail

This shows detailed information on the TLS connections. If the connection to the CUCM is cleartext, the State would show "TCPOK" like so:

PhoneProxyASA# show tls-proxy sessions detail
outside 172.18.22.223:2658 DMZ 192.168.2.3:2000 P:0xd5f4fc20(mytls)
S:0xd6193430 byte 37124
  Client: State SSLOK  Cipher AES128-SHA Ch 0xd49090d8 TxQSize 0
LastTxLeft 0 Flags 0x31
  Server: State TCPOK  Cipher N/A        Ch 0xd4909118 TxQSize 0
LastTxLeft 0 Flags 0x8

show phone-proxy signaling-sessions

PhoneProxyASA# show phone-proxy signaling-sessions 
outside 172.18.254.25:19931 inside 172.18.124.230:2000
  Local Media (audio) conn: 172.18.254.25/22988 to 14.36.107.91/26830
    Local SRTP key set : Remote SRTP key set
  Remote Media (audio) conn: 14.36.107.91/26830 to 14.36.107.91/29724

outside 172.18.254.73:50124 inside 172.18.124.230:2000
  Local Media (audio) conn: 172.18.254.73/29836 to 14.36.107.91/29724
    Local SRTP key set : Remote SRTP key set
  Remote Media (audio) conn: 14.36.107.91/29724 to 14.36.107.91/26830

PhoneProxyASA#

show asp table classify domain app-redirect

This shows all the app-redirect rules created by the phone-proxy. There should be one entry for each phone to the CUCM IF the phone was configured as a nonsecure phone.

PhoneProxyASA# show asp table classify domain app-redirect

Interface _phone_proxy_ifc:

Interface inside:

Interface outside:
in  id=0xd5b85918, priority=12, domain=app-redirect, deny=false
     hits=1, user_data=0xd007, cs_id=0x0, flags=0x0, protocol=6
     src ip=172.18.254.73, mask=255.255.255.255, port=0
     dst ip=14.36.107.95, mask=255.255.255.255, port=2443, dscp=0x0
in  id=0xd59f0d10, priority=12, domain=app-redirect, deny=false
     hits=0, user_data=0xdc0e, cs_id=0x0, flags=0x0, protocol=6
     src ip=172.18.254.73, mask=255.255.255.255, port=0
     dst ip=14.36.107.95, mask=255.255.255.255, port=3804, dscp=0x0
in  id=0xd5ba9a28, priority=12, domain=app-redirect, deny=false
     hits=1, user_data=0xd007, cs_id=0x0, flags=0x0, protocol=6
     src ip=172.18.254.25, mask=255.255.255.255, port=0
     dst ip=14.36.107.95, mask=255.255.255.255, port=2443, dscp=0x0
in  id=0xd59d8f58, priority=12, domain=app-redirect, deny=false
     hits=0, user_data=0xdc0e, cs_id=0x0, flags=0x0, protocol=6
     src ip=172.18.254.25, mask=255.255.255.255, port=0
     dst ip=14.36.107.95, mask=255.255.255.255, port=3804, dscp=0x0

Interface identity:

Last clearing of hits counters: Never
PhoneProxyASA#

show asp table classify domain inspect-phone-proxy

This shows the classification rule to punt all TFTP traffic destined to the configured phone-proxy TFTP server to the inspect-phone-proxy engine. The classification rule should show the TFTP server's global address for that particular interface. If the phone-proxy was applied globally, there should be a classification rule for each interface except the interface it resides on. This rule is built when the phone-proxy config is applied to a service-policy in MPF, and will build the rules based upon the existing translation config on the firewall. Therefore, if you configure the phone proxy and apply it and then later put the NAT config in, the asp table rule will be incorrect (it will show the local ip for the call manager, not the global ip like it should). Therefore, ensure that you configure nat first, THEN apply the phone-proxy mpf to a service-policy.

PhoneProxyASA#show asp table classify domain inspect-phone-proxy
Interface _phone_proxy_ifc: 

Interface inside:

Interface outside:
in  id=0xd5ba1640, priority=73, domain=inspect-phone-proxy, deny=false
     hits=4200, user_data=0xd59beff8, cs_id=0x0, reverse, flags=0x0, protocol=17 
     src ip=0.0.0.0, mask=0.0.0.0, port=0
     dst ip=14.36.107.95, mask=255.255.255.255, port=69, dscp=0x0
in  id=0xd59ca8b8, priority=73, domain=inspect-phone-proxy, deny=false
     hits=0, user_data=0xd48b62b0, cs_id=0x0, reverse, flags=0x0, protocol=17
     src ip=0.0.0.0, mask=0.0.0.0, port=0
     dst ip=14.36.107.95, mask=255.255.255.255, port=69, dscp=0x0

Interface identity:

Last clearing of hits counters: Never
PhoneProxyASA#

show conn | inc p

This shows all the connections that have gone through the inspect-phone-proxy which inspects the TFTP traffic.

PhoneProxyASA# show conn | inc p
9 in use, 67 most used
UDP outside 172.18.254.25:8872 inside 172.18.124.230:32847, idle 0:00:02, bytes 4076, flags p-
UDP outside 172.18.254.25:62644 inside 172.18.124.230:39392, idle 0:00:03, bytes 4486, flags p-
TCP outside 172.18.124.241(172.18.254.25):29544 inside 172.18.124.230:2000, idle 0:00:01, bytes 894, flags UOB
UDP outside 172.18.254.25:8872 inside 172.18.124.230:69, idle 0:00:02, bytes 32, flags p-
UDP outside 172.18.254.25:62644 inside 172.18.124.230:69, idle 0:00:03, bytes 0, flags p-
TCP outside 172.18.124.241(172.18.254.73):50124 inside 172.18.124.230:2000, idle 0:00:14, bytes 22969, flags UIOB
PhoneProxyASA#

Syslogs

New syslogs relating to the phone-proxy feature:

%ASA-4-446001 - Maximum number of configured TLS proxy sessions reached

%ASA-4-446001: Maximum TLS Proxy session limit of max_sess reached.

%ASA-4-446002 - License exceeded

%ASA-4-446002: Denied TLS Proxy session from outside:10.10.10.2/49572 to inside:192.168.1.2/2000, licensed UC Proxy session limit of 20 exceeded

Sample syslogs from when a phone connected to the phone-proxy reboots and connects back in

%ASA-5-305011: Built dynamic UDP translation from outside:172.18.254.73/53011 to 
inside:172.18.124.241/60692
%ASA-6-302015: Built inbound UDP connection 4338 for outside:172.18.254.73/53011 
(172.18.124.241/60692) to inside:172.18.124.230/69 (14.36.107.95/69)
%ASA-6-302015: Built inbound UDP connection 4339 for outside:172.18.254.73/53011 
(172.18.124.241/60692) to inside:172.18.124.230/4677 (14.36.107.95/4677)
%ASA-7-111009: User 'enable_15' executed cmd: show logging
%ASA-6-305011: Built dynamic UDP translation from outside:172.18.254.73/53012 to 
inside:172.18.124.241/63537
%ASA-6-302015: Built inbound UDP connection 4340 for outside:172.18.254.73/53012 
(172.18.124.241/63537) to inside:172.18.124.230/69 (14.36.107.95/69)
%ASA-6-302015: Built inbound UDP connection 4341 for outside:172.18.254.73/53012 
(172.18.124.241/63537) to inside:172.18.124.230/32851 (14.36.107.95/32851)
%ASA-6-305011: Built dynamic TCP translation from outside:172.18.254.73/50125 to 
inside:172.18.124.241/37554
%ASA-6-302013: Built inbound TCP connection 4342 for outside:172.18.254.73/50125 
(172.18.124.241/37554) to inside:172.18.124.230/2000 (14.36.107.95/2443)
%ASA-6-725001: Starting SSL handshake with client outside:172.18.254.73/50125 for TLSv1 session.
%ASA-7-725010: Device supports the following 4 cipher(s).
%ASA-7-725011: Cipher[1] : RC4-SHA
%ASA-7-725011: Cipher[2] : AES128-SHA
%ASA-7-725011: Cipher[3] : AES256-SHA
%ASA-7-725011: Cipher[4] : DES-CBC3-SHA
%ASA-7-725008: SSL client outside:172.18.254.73/50125 proposes the following 2 cipher(s).
%ASA-7-725011: Cipher[1] : AES256-SHA
%ASA-7-725011: Cipher[2] : AES128-SHA
%ASA-7-725012: Device chooses cipher : AES128-SHA for the SSL session with client 
outside:172.18.254.73/50125
%ASA-7-717025: Validating certificate chain containing 1 certificate(s).
%ASA-7-717029: Identified client certificate within certificate chain. 
serial number: 01, subject name: cn=SEP0007EBF0EE54.
%ASA-7-717030: Found a suitable trustpoint capf_trustpoint to validate certificate.
%ASA-6-717022: Certificate was successfully validated. serial number: 01, 
subject name:  cn=SEP0007EBF0EE54.
%ASA-6-717028: Certificate chain was successfully validated with warning, 
revocation status was not checked.
%ASA-6-725002: Device completed SSL handshake with client outside:172.18.254.73/50125
%ASA-6-305011: Built dynamic TCP translation from outside:172.18.254.73/52675 
to inside:172.18.124.241/45909
%ASA-7-711002: Task ran for 8 msec, Process = Dispatch Unit, PC = 8172a27, Traceback = 
%ASA-7-711002: Task ran for 8 msec, Process = Dispatch Unit, PC = 8172a27, 
Traceback =   0x08172A27  0x0805E983
%ASA-6-305012: Teardown dynamic TCP translation from outside:172.18.254.73/50124 to 
inside:172.18.124.241/51711 duration 1:41:06
%ASA-6-305011: Built dynamic UDP translation from outside:172.18.254.73/53013 to 
inside:172.18.124.241/58122
%ASA-6-302015: Built inbound UDP connection 4343 for outside:172.18.254.73/53013 
(172.18.124.241/58122) to inside:172.18.124.230/69 (14.36.107.95/69)
%ASA-6-302015: Built inbound UDP connection 4344 for outside:172.18.254.73/53013 
(172.18.124.241/58122) to inside:172.18.124.230/32852 (14.36.107.95/32852)
%ASA-7-111009: User 'enable_15' executed cmd: show logging
%ASA-6-305011: Built dynamic UDP translation from outside:172.18.254.73/53014 to 
inside:172.18.124.241/54570
%ASA-6-302015: Built inbound UDP connection 4345 for outside:172.18.254.73/53014 
(172.18.124.241/54570) to inside:172.18.124.230/69 (14.36.107.95/69)
%ASA-6-302015: Built inbound UDP connection 4346 for outside:172.18.254.73/53014 
(172.18.124.241/54570) to inside:172.18.124.230/32853 (14.36.107.95/32853)
%ASA-6-305011: Built dynamic UDP translation from outside:172.18.254.73/53015 to 
inside:172.18.124.241/63316
%ASA-6-302015: Built inbound UDP connection 4347 for outside:172.18.254.73/53015 
(172.18.124.241/63316) to inside:172.18.124.230/69 (14.36.107.95/69)
%ASA-6-302015: Built inbound UDP connection 4348 for outside:172.18.254.73/53015 
(172.18.124.241/63316) to inside:172.18.124.230/32854 (14.36.107.95/32854)
%ASA-7-111009: User 'enable_15' executed cmd: show logging
%ASA-7-111009: User 'enable_15' executed cmd: show logging

Debugs with Sample Output

debug phone-proxy tftp

This debug will output information about the tftp session proxied by the firewall.

PhoneProxyASA# debug phone-proxy tftp 
PhoneProxyASA#  
PhoneProxyASA# !- The phone is now rebooted
PhoneProxyASA# 
PhoneProxyASA# PP: 172.18.254.25/37212 requesting CTLSEP0009B7D0EEA7.tlv
PP: opened 0x8685366
PP: Data Block 1 forwarded from 14.36.107.95/29840 to 172.18.254.25/37212 ingress ifc outside
PP: Received ACK Block 1 from outside:172.18.254.25/37212 to inside:172.18.124.230
PP: Data Block 2 forwarded to 172.18.254.25/37212
PP: Received ACK Block 2 from outside:172.18.254.25/37212 to inside:172.18.124.230
PP: Data Block 3 forwarded to 172.18.254.25/37212
PP: Received ACK Block 3 from outside:172.18.254.25/37212 to inside:172.18.124.230
PP: Data Block 4 forwarded to 172.18.254.25/37212
PP: Received ACK Block 4 from outside:172.18.254.25/37212 to inside:172.18.124.230
PP: Data Block 5 forwarded to 172.18.254.25/37212
PP: Received ACK Block 5 from outside:172.18.254.25/37212 to inside:172.18.124.230
PP: Data Block 6 forwarded to 172.18.254.25/37212
PP: Received ACK Block 6 from outside:172.18.254.25/37212 to inside:172.18.124.230
PP: Data Block 7 forwarded to 172.18.254.25/37212
PP: Received ACK Block 7 from outside:172.18.254.25/37212 to inside:172.18.124.230
PP: Data Block 8 forwarded to 172.18.254.25/37212
PP: Received ACK Block 8 from outside:172.18.254.25/37212 to inside:172.18.124.230
PP: Data Block 9 forwarded to 172.18.254.25/37212
PP: Received ACK Block 9 from outside:172.18.254.25/37212 to inside:172.18.124.230
PP: TFTP session complete, all data sent
PP: 172.18.254.25/53261 requesting SEP0009B7D0EEA7.cnf.xml.sgn
PP: opened 0x8693dd2
PP: Received Data Block 1 from inside:172.18.124.230/32851 to outside:172.18.254.25/53261
     Received Block 1
PP: Acked Block #1 from 172.18.124.241/49633 to 172.18.124.230/32851
PP: Received Data Block 2 from inside:172.18.124.230/32851 to outside:172.18.254.25/53261
     Received Block 2
PP: Acked Block #2 from 172.18.124.241/49633 to 172.18.124.230/32851
PP: Received Data Block 3 from inside:172.18.124.230/32851 to outside:172.18.254.25/53261
     Received Block 3
PP: Acked Block #3 from 172.18.124.241/49633 to 172.18.124.230/32851
PP: Received Data Block 4 from inside:172.18.124.230/32851 to outside:172.18.254.25/53261
     Received Block 4
PP: Acked Block #4 from 172.18.124.241/49633 to 172.18.124.230/32851
PP: Received Data Block 5 from inside:172.18.124.230/32851 to outside:172.18.254.25/53261
     Received Block 5
PP: Acked Block #5 from 172.18.124.241/49633 to 172.18.124.230/32851
PP: Received Data Block 6 from inside:172.18.124.230/32851 to outside:172.18.254.25/53261
     Received Block 6
PP: Acked Block #6 from 172.18.124.241/49633 to 172.18.124.230/32851
PP: Received Data Block 7 from inside:172.18.124.230/32851 to outside:172.18.254.25/53261
     Received Block 7
PP: Acked Block #7 from 172.18.124.241/49633 to 172.18.124.230/32851
PP: Received Data Block 8 from inside:172.18.124.230/32851 to outside:172.18.254.25/53261
     Received Block 8
PP: Acked Block #8 from 172.18.124.241/49633 to 172.18.124.230/32851
PP: Modifying to encrypted mode.
PP: Modifying to TLS as the transport layer protocol.
PP: Data Block 1 forwarded from 14.36.107.95/32851 to 172.18.254.25/53261
PP: Received ACK Block 1 from outside:172.18.254.25/53261 to inside:172.18.124.230
PP: Data Block 2 forwarded to 172.18.254.25/53261
PP: Received ACK Block 2 from outside:172.18.254.25/53261 to inside:172.18.124.230
PP: Data Block 3 forwarded to 172.18.254.25/53261
PP: Received ACK Block 3 from outside:172.18.254.25/53261 to inside:172.18.124.230
PP: Data Block 4 forwarded to 172.18.254.25/53261
PP: Received ACK Block 4 from outside:172.18.254.25/53261 to inside:172.18.124.230
PP: Data Block 5 forwarded to 172.18.254.25/53261
PP: Received ACK Block 5 from outside:172.18.254.25/53261 to inside:172.18.124.230
PP: Data Block 6 forwarded to 172.18.254.25/53261
PP: Received ACK Block 6 from outside:172.18.254.25/53261 to inside:172.18.124.230
PP: Data Block 7 forwarded to 172.18.254.25/53261
PP: Received ACK Block 7 from outside:172.18.254.25/53261 to inside:172.18.124.230
PP: Data Block 8 forwarded to 172.18.254.25/53261
PP: Received ACK Block 8 from outside:172.18.254.25/53261 to inside:172.18.124.230
PP: TFTP session complete, all data sent
PP: Retrieved MAC 0009.b7d0.eea7 from subject-name cn=SEP0009B7D0EEA7, mac string 0009B7D0EEA7
PP: Found phone device d5b94218
PP: 172.18.254.25/14201 requesting SEP0009B7D0EEA7.cnf.xml.sgn
PP: opened 0x86abd3a
PP: Received Data Block 1 from inside:172.18.124.230/32851 to outside:172.18.254.25/14201
     Received Block 1
PP: Acked Block #1 from 172.18.124.241/6550 to 172.18.124.230/32851
PP: Received Data Block 2 from inside:172.18.124.230/32851 to outside:172.18.254.25/14201
     Received Block 2
PP: Acked Block #2 from 172.18.124.241/6550 to 172.18.124.230/32851
PP: Received Data Block 3 from inside:172.18.124.230/32851 to outside:172.18.254.25/14201
     Received Block 3
PP: Acked Block #3 from 172.18.124.241/6550 to 172.18.124.230/32851
PP: Received Data Block 4 from inside:172.18.124.230/32851 to outside:172.18.254.25/14201
     Received Block 4
PP: Acked Block #4 from 172.18.124.241/6550 to 172.18.124.230/32851
PP: Received Data Block 5 from inside:172.18.124.230/32851 to outside:172.18.254.25/14201
     Received Block 5
PP: Acked Block #5 from 172.18.124.241/6550 to 172.18.124.230/32851
PP: Received Data Block 6 from inside:172.18.124.230/32851 to outside:172.18.254.25/14201
     Received Block 6
PP: Acked Block #6 from 172.18.124.241/6550 to 172.18.124.230/32851
PP: Received Data Block 7 from inside:172.18.124.230/32851 to outside:172.18.254.25/14201
     Received Block 7
PP: Acked Block #7 from 172.18.124.241/6550 to 172.18.124.230/32851
PP: Received Data Block 8 from inside:172.18.124.230/32851 to outside:172.18.254.25/14201
     Received Block 8
PP: Acked Block #8 from 172.18.124.241/6550 to 172.18.124.230/32851
PP: Modifying to encrypted mode.
PP: Modifying to TLS as the transport layer protocol.
PP: 172.18.254.25/47823 requesting RINGLIST.XML.sgn
PP: opened 0x86bf8f6
PP: Data Block 1 forwarded from 14.36.107.95/32851 to 172.18.254.25/14201
PP: Received Data Block 1 from inside:172.18.124.230/32851 to outside:172.18.254.25/47823
     Received Block 1
PP: Acked Block #1 from 172.18.124.241/13065 to 172.18.124.230/32851
PP: Received Data Block 2 from inside:172.18.124.230/32851 to outside:172.18.254.25/47823
     Received Block 2
PP: Acked Block #2 from 172.18.124.241/13065 to 172.18.124.230/32851
PP: Received ACK Block 1 from outside:172.18.254.25/14201 to inside:172.18.124.230
PP: Data Block 2 forwarded to 172.18.254.25/14201
PP: Received Data Block 3 from inside:172.18.124.230/32851 to outside:172.18.254.25/47823
     Received Block 3
PP: Acked Block #3 from 172.18.124.241/13065 to 172.18.124.230/32851
PP: Received Data Block 4 from inside:172.18.124.230/32851 to outside:172.18.254.25/47823
     Received Block 4
PP: Acked Block #4 from 172.18.124.241/13065 to 172.18.124.230/32851
PP: Received Data Block 5 from inside:172.18.124.230/32851 to outside:172.18.254.25/47823
     Received Block 5
PP: Acked Block #5 from 172.18.124.241/13065 to 172.18.124.230/32851
PP: Data Block 1 forwarded from 14.36.107.95/32851 to 172.18.254.25/47823
PP: Received ACK Block 2 from outside:172.18.254.25/14201 to inside:172.18.124.230
PP: Data Block 3 forwarded to 172.18.254.25/14201
PP: Received ACK Block 1 from outside:172.18.254.25/47823 to inside:172.18.124.230
PP: Data Block 2 forwarded to 172.18.254.25/47823
PP: Received ACK Block 3 from outside:172.18.254.25/14201 to inside:172.18.124.230
PP: Data Block 4 forwarded to 172.18.254.25/14201
PP: Received ACK Block 2 from outside:172.18.254.25/47823 to inside:172.18.124.230
PP: Data Block 3 forwarded to 172.18.254.25/47823
PP: Received ACK Block 4 from outside:172.18.254.25/14201 to inside:172.18.124.230
PP: Data Block 5 forwarded to 172.18.254.25/14201
PP: Received ACK Block 3 from outside:172.18.254.25/47823 to inside:172.18.124.230
PP: Data Block 4 forwarded to 172.18.254.25/47823
PP: Received ACK Block 5 from outside:172.18.254.25/14201 to inside:172.18.124.230
PP: Data Block 6 forwarded to 172.18.254.25/14201
PP: Received ACK Block 4 from outside:172.18.254.25/47823 to inside:172.18.124.230
PP: Data Block 5 forwarded to 172.18.254.25/47823
PP: Received ACK Block 6 from outside:172.18.254.25/14201 to inside:172.18.124.230
PP: Data Block 7 forwarded to 172.18.254.25/14201
PP: Received ACK Block 5 from outside:172.18.254.25/47823 to inside:172.18.124.230
PP: TFTP session complete, all data sent
PP: Received ACK Block 7 from outside:172.18.254.25/14201 to inside:172.18.124.230
PP: Data Block 8 forwarded to 172.18.254.25/14201
PP: 172.18.254.25/56992 requesting DISTINCTIVERINGLIST.XML.sgn
PP: opened 0x86c9112
PP: Received ACK Block 8 from outside:172.18.254.25/14201 to inside:172.18.124.230
PP: TFTP session complete, all data sent
PP: Received Data Block 1 from inside:172.18.124.230/32851 to outside:172.18.254.25/56992
     Received Block 1
PP: Acked Block #1 from 172.18.124.241/62582 to 172.18.124.230/32851
PP: Received Data Block 2 from inside:172.18.124.230/32851 to outside:172.18.254.25/56992
     Received Block 2
PP: Acked Block #2 from 172.18.124.241/62582 to 172.18.124.230/32851
PP: Data Block 1 forwarded from 14.36.107.95/32851 to 172.18.254.25/56992
PP: Received ACK Block 1 from outside:172.18.254.25/56992 to inside:172.18.124.230
PP: Data Block 2 forwarded to 172.18.254.25/56992
PP: Received ACK Block 2 from outside:172.18.254.25/56992 to inside:172.18.124.230
PP: TFTP session complete, all data sent

PhoneProxyASA#

debug phone-proxy media

PhoneProxyASA# debug phone-proxy media
PhoneProxyASA# 
PhoneProxyASA# !- A call is made from one phone to another
PhoneProxyASA#
PhoneProxyASA# 
snp_client_sess_create: Creating client_sess 14.36.107.91/25752 172.18.254.73/24316
snp_media_sess_lock: locking media_sess 14.36.107.91/25752 1
Creating new media session in SNP 14.36.107.91/25752
Setting remote_side SRTP params in SNP 14.36.107.91/25752
SNP_SRTP::master_key and salt 1c9050bb8e388149b89b092e4dca2275 1c9050bb8e388149b89b092e4dca2275
snp_media_sess_lock: locking media_sess 14.36.107.91/25752 2
Rmt media is NULL 14.36.107.91/39012
Getting remote SRTP params in SNP 14.36.107.91/25752
snp_media_sess_lock: locking media_sess 14.36.107.91/25752 3
Remote SRTP params for 14.36.107.91/25752 already set
Setting local SRTP params in SNP 14.36.107.91/25752
SNP_SRTP::master_key and salt e8f9f25522578aff38d32d95895e40b4 e8f9f25522578aff38d32d95895e40b4
snp_client_sess_create: Creating client_sess 14.36.107.91/29668 172.18.254.25/17472
snp_media_sess_lock: locking media_sess 14.36.107.91/29668 1
Creating new media session in SNP 14.36.107.91/29668
Remote SRTP params for 14.36.107.91/25752 already set
Local SRTP params for 14.36.107.91/25752 already set
Setting remote_side SRTP params in SNP 14.36.107.91/29668
SNP_SRTP::master_key and salt e8f9f25522578aff38d32d95895e40b4 e8f9f25522578aff38d32d95895e40b4
snp_media_sess_lock: locking media_sess 14.36.107.91/25752 4
snp_media_sess_lock: locking media_sess 14.36.107.91/25752 5
snp_media_sess_lock: locking media_sess 14.36.107.91/29668 2
Getting remote SRTP params in SNP 14.36.107.91/29668
snp_media_sess_lock: locking media_sess 14.36.107.91/29668 3
Remote SRTP params for 14.36.107.91/29668 already set
Setting local SRTP params in SNP 14.36.107.91/29668
SNP_SRTP::master_key and salt 1c9050bb8e388149b89b092e4dca2275 1c9050bb8e388149b89b092e4dca2275
snp_media_sess_lock: locking media_sess 14.36.107.91/29668 4
snp_media_sess_lock: locking media_sess 14.36.107.91/29668 5
SNP_SRTP::Remote media_session found for 14.36.107.91/25752 lcl_ip/lcl_port 14.36.107.91/29668
SNP_SRTP::Setting rmt_pp_ip 14.36.107.91 for 14.36.107.91/25752
SNP_SRTP::Setting passthrough
SNP_SRTP::Setting client_port to sport 24316
SNP_SRTP::Remote media_session found for 14.36.107.91/29668 lcl_ip/lcl_port 14.36.107.91/25752
SNP_SRTP::Setting passthrough
SNP_SRTP::Setting client_port to sport 49114

PhoneProxyASA# 
PhoneProxyASA# !- Call is now connected
PhoneProxyASA# 
PhoneProxyASA# !- Call is hung up
PhoneProxyASA#
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/25752 4
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/25752 3
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/29668 4
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/29668 3
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/25752 2
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/25752 1
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/29668 2
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/29668 1
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/25752 0
snp_media_sess_release: releasing media_sess 14.36.107.91/25752
snp_media_sess_unlock: unlocking media_sess 14.36.107.91/29668 0
snp_media_sess_release: releasing media_sess 14.36.107.91/29668

PhoneProxyASA#

debug phone-proxy signaling

PhoneProxyASA# debug phone-proxy signaling 
PhoneProxyASA# 
PhoneProxyASA# 
PhoneProxyASA# ! One phone now calls another...
PhoneProxyASA# 
PhoneProxyASA# 
Inspect Skinny: generating SRTP key
PP_SIG:: Setting rmt SRTP params in pp_cl d5b943f8
PP_SIG::master_key and salt 013351f6a163735e469307253dfa4c11 013351f6a163735e469307253dfa4c11
Inspect Skinny: generating SRTP key
PP_SIG:: Setting rmt SRTP params in pp_cl d59db4d8
PP_SIG::master_key and salt 8704186bbb636c51079eb312e4d8d77d 8704186bbb636c51079eb312e4d8d77d
PP_SIG::pp_update_media_info: using conn's laddr 172.18.254.73/27754
PP_SIG::Updating lcl media info 172.18.254.73/27754
PP_SIG::Setting lcl_media_sess 14.36.107.91/29596
PP_SIG::Updating lcl PP media info 14.36.107.91/29596
PP_SIG:: calling np_media_sess_set_media_conns
PP_SIG::pp_update_media_info: Found media_sess 14.36.107.91/29596
Called np_nat_api_determine_location: 14.36.107.91/29596
PP_SIG::Updating rmt media info 14.36.107.91/29596
PP_SIG::Setting rmt_media_sess 14.36.107.91/29596
PP_SIG::Updating rmt PP media info 14.36.107.91/29596
PP_SIG:: Getting lcl SRTP params in pp_cl d59db4d8
PP_SIG::pp_update_media_info: using conn's laddr 172.18.254.25/20912
PP_SIG::Updating lcl media info 172.18.254.25/20912
PP_SIG::Setting lcl_media_sess 14.36.107.91/25654
PP_SIG::Updating lcl PP media info 14.36.107.91/25654
PP_SIG:: calling np_media_sess_set_media_conns
PP_SIG:: calling np_media_sess_set_media_conns
PP_SIG:: calling np_media_sess_set_media_conns
PP_SIG::pp_update_media_info: Found media_sess 14.36.107.91/25654
Called np_nat_api_determine_location: 14.36.107.91/25654
PP_SIG::Updating rmt media info 14.36.107.91/25654
PP_SIG::Setting rmt_media_sess 14.36.107.91/25654
PP_SIG::Updating rmt PP media info 14.36.107.91/25654
PP_SIG:: Getting lcl SRTP params in pp_cl d5b943f8
PP_SIG:: calling np_media_sess_set_media_conns
PP_SIG:: calling np_media_sess_set_media_conns
PhoneProxyASA#
PhoneProxyASA#
PhoneProxyASA#
PhoneProxyASA# !- Call is ended by called party
PhoneProxyASA# 
PhoneProxyASA# 
PP_SIG::pp_clear_lcl_media_ptr_values: calling media_sess_unlock on d59c35f8
PP_SIG::pp_clear_rmt_media_ptr_values: calling media_sess_unlock on d5b90218
PP_SIG::pp_clear_lcl_media_ptr_values: calling media_sess_unlock on d5b90218
PP_SIG::pp_clear_rmt_media_ptr_values: calling media_sess_unlock on d59c35f8

PhoneProxyASA#

Kapil Atrish · ‎05-26-2010

Hi,

ASA Version 8.0(5)

I've a customer setup where output of following command is showing CCM Internal Ip address and not the global ip address.

show asp table classify domain inspect-phone-proxy

All other commands show the correct output, calling is also working fine.

Customer confirmed that he configured NAT first and then MPF. I can see one Global policy is configured but the Secure SCCP class-map is not called inside that and I believe it has nothing to do with my problem. See below MPF configuration:

class-map secure_sccp
match port tcp eq 2443
class-map inspection_default
match default-inspection-traffic
!
!
policy-map type inspect dns preset_dns_map
parameters
message-length maximum 512
policy-map global_policy
class inspection_default
inspect dns preset_dns_map
inspect ftp
inspect h323 h225
inspect h323 ras
inspect netbios
inspect rsh
inspect rtsp
inspect skinny
inspect esmtp
inspect sqlnet
inspect sunrpc
inspect tftp
inspect sip
inspect xdmcp
policy-map voice_policy
class secure_sccp
inspect skinny phone-proxy asa-phone-proxy
!
service-policy global_policy global
service-policy voice_policy interface outside

I am curious to know what issues he may face due to this mismatch, how to rectify it, any impact on ongoing calls?

Thanks,

inner_silence

tahequivoice · ‎05-05-2011

This is a very good doc on the Phone Proxy, Thank you.

I have run into a problem though, which I dont think is covered here. I have no audio, including ringback when making an outside call, not to internal extensions. We use external voice gateways to send the calls out, so when the proxy phone makes the call, it connects, the remote phone can pick up the call, it connects, and no voice. I can see the connection on the ASA with the gateway IP and the proxy phone IP, so I can see that it has connected, but I have nothing after that.

In the media debug I can see the call connecting to the gateway using the MTA, gets 4 sess_lock, and nothing after that. Is there a translation I need to setup on the ASA for the Phone Proxy to work with external gateways?

Jay Johnston · ‎05-05-2011

The problem is most likely due to media-data packet routing, or media-packets being dropped somewhere in the network. In the case that media packets are routed incorrectly through the network (Discussed in the section above titled "One way, or no-way voice audio when call established") you might see syslogs like this, which indicate the firewall is receiving the media data on an unexpected interface:

%ASA-7-710005: UDP request discarded from 10.99.22.3/22431 to outside:192.168.1.2/28230
%ASA-7-710005: UDP request discarded from 10.99.22.3/22431 to outside:192.168.1.2/28230
%ASA-7-710005: UDP request discarded from 10.99.22.3/22431 to outside:192.168.1.2/28230
%ASA-7-710005: UDP request discarded from 10.99.22.3/22431 to outside:192.168.1.2/28230
%ASA-7-710005: UDP request discarded from 10.99.22.3/22431 to outside:192.168.1.2/28230
%ASA-7-710005: UDP request discarded from 10.99.22.3/22431 to outside:192.168.1.2/28230

Packet captures taken on the firewall interfaces for traffic sourced and destined 
to the MTA address will probably help track down where the problem is (Packet capture ASA/PIX - FWSM). 
However, these types of call routing-problems can be very complex, and it might be best to 
open a case with the TAC.

eng__mohamed · ‎10-04-2011

i have the problem i configure the ASA with non secure

but the phone can not register

PP: Remote phone at 2.2.2.50/49152 requesting CTLSEP0013809EA017.tlv from 10.2.100.1/69

PP: Created entry for secure device outside:2.2.2.50, MAC 0013.809e.a017, current count 1, list count 1

PP: ASA sending local CTL file on disk myctl to remote phone, opened 0xe79fb2

PP: Data Block 1 sent from ASA at 2.2.2.10/25269 to remote phone at 2.2.2.50/49152, ingress ifc

PP: Received ACK for Block 1 from remote phone outside:2.2.2.50/49152 to ASA at inside:10.2.100.1

PP: Data Block 2 sent from ASA to remote phone at 2.2.2.50/49152

PP: Received ACK for Block 2 from remote phone outside:2.2.2.50/49152 to ASA at inside:10.2.100.1

PP: Data Block 3 sent from ASA to remote phone at 2.2.2.50/49152

PP: Received ACK for Block 3 from remote phone outside:2.2.2.50/49152 to ASA at inside:10.2.100.1

PP: Data Block 4 sent from ASA to remote phone at 2.2.2.50/49152

PP: Received ACK for Block 4 from remote phone outside:2.2.2.50/49152 to ASA at inside:10.2.100.1

PP: Data Block 5 sent from ASA to remote phone at 2.2.2.50/49152

PP: Received ACK for Block 5 from remote phone outside:2.2.2.50/49152 to ASA at inside:10.2.100.1

PP: Data Block 6 sent from ASA to remote phone at 2.2.2.50/49152

PP: Received ACK for Block 6 from remote phone outside:2.2.2.50/49152 to ASA at inside:10.2.100.1

PP: Data Block 7 sent from ASA to remote phone at 2.2.2.50/49152

PP: Received ACK for Block 7 from remote phone outside:2.2.2.50/49152 to ASA at inside:10.2.100.1

PP: CTL file TFTP session complete, CTL file has been successfully sent to the remote phone.

%ASA-6-302015: Built inbound UDP connection 464 for outside:2.2.2.50/49153 (2.2.2.50/49153) to inside:10.2.100.1/69 (2.2.2.10/69)

PP: Remote phone at 2.2.2.50/49153 requesting SEP0013809EA017.cnf.xml.sgn from 10.2.100.1/69

PP: The remote phone is requesting file SEP0013809EA017.cnf.xml.sgn.

PP: Removing .sgn extension, ASA is requesting file SEP0013809EA017.cnf.xml from Call Manager TFTP server.

PP: ASA sent request for SEP0013809EA017.cnf.xml sourced from outside:2.2.2.50 to inside:10.2.100.1, opened 0xe8c0fe

%ASA-6-302016: Teardown UDP connection 435 for outside:2.2.2.50/49157 to inside:10.2.100.1/69 duration 0:02:20 bytes 208

%ASA-7-710005: UDP request discarded from 10.2.2.14/17500 to inside:10.2.2.255/17500

PP: Remote phone at 2.2.2.50/49153 requesting SEP0013809EA017.cnf.xml.sgn from 10.2.100.1/69

PP: Client outside:2.2.2.50/49153 retransmitting request for Config file SEP0013809EA017.cnf.xml.sgn

PP: The remote phone is requesting file SEP0013809EA017.cnf.xml.sgn.

PP: Removing .sgn extension, ASA is requesting file SEP0013809EA017.cnf.xml from Call Manager TFTP server.

PP: ASA sent request for SEP0013809EA017.cnf.xml sourced from outside:2.2.2.50 to inside:10.2.100.1, opened 0xe8c0fe

%ASA-7-710005: UDP request discarded from 10.2.2.14/53856 to inside:255.255.255.255/43440