Cisco 8811 phones and AnyConnect VPN - phone not attempting to connect

[russjstewart]

Hi There,

I am hoping someone out there can tell me if what I am trying to do is even possible and if so what I am doing wrong. or even point me in the right direction.

We are trying to get 8811 to connect to our CUCM 12.0 server using an ASA 5516 and the AnyConnect VPN. The ASA has the correct license and has been configured as has CUCM. When I connect the phone to an external internet connection a wireshark trace shows the phone trying to  ping the publisher and subscriber using the internal address ( I assume this is part of the auto network detection process) after 20 seconds or so after  the "detecting network" appears on the phone I get a message that he VPN has failed. The wireshark trace however shows nothing being sent from the phone to the network during this period. It does not even try to do a DNS lookup on the configured group URL that used a FQDN. The .cnf.xml.sgn file for the phone does containing the URL for the external ASA interface as well as the hash that matches the ASA certificate.

Any help would be greatly appreciated

Thanks

[HARIS_HUSSAIN]

1) Have you configured all the steps as per belog blog

https://www.cisco.com/c/en/us/td/docs/voice_ip_comm/cuipph/8800-series/english/adminguide/P881_BK_C136782F_00_cisco-ip-phone-8800_series/P881_BK_C136782F_00_cisco-ip-phone-8811-8841_chapter_01011.html

2) Phone should be able to register via internal network and download the Configuration file with VPN Certificate Hash value.

Check the Phone configuration file in CUCM if it has the hash value of ASA Certificate.

3) Try to collect the IP Phone Console logs and attache here. YOu can follow below guide to collect logs and other troubleshooting steps.

https://www.cisco.com/c/en/us/support/docs/security/anyconnect-secure-mobility-client/116162-trouble-anyconnect-vpn-phone-00.html
.

Thanks,

Haris

.

**** Please rate helpful post; Mark "Accept as a Solution" if applicable

Thanks,
Haris

[russjstewart]

Hi Haris,
Thank you for taking the time to reply to my query. I am pretty sure I have followed the steps in the 1st URL to set the VPN up.
The phone does register with CUCM on the internal network, and the XML file does down load to it. I have checked the hash in the XML file and it does match the ASA certificate.
When the phone goes onto the external network, it boots up then displays "detecting network" for about 30 seconds, during this time it tries to connect to the TFTP/CUCM servers using the internal IP addresses ( I assume this is part the auto detect process to see if it needs to use the VPN or not). After 30 seconds it displays a message about connecting to the VPN, then within a second or two VPN connection fails. Once it goes to connecting to the VPN the phone does not send any traffic to the network ( I am running SPAN on the port the phone is connected to), even when you hit the retry button, no data is sent. I am not even seeing a DNS lookup for the domain name in the VPN URL.

Console Logs from the Phone are (apologies for the formatting


4 - Cisco Systems - # RELEASE Model=88xx Version=sip88xx.12-1-1SR1-4

[TZ=GMT+00:00 ] Mon Feb 18 05:30:01 2019

=============================================================[V04][HW ver: V01

][4]

3462 INF Feb 18 05:30:01.768207 syslogd forced rotation

3463 NOT Feb 18 05:30:01.768618 (317:317) sarchmon-/var/log/messages.3 not present

3464 DEB Feb 18 05:30:37.602606 (199:1272) restart_mgr-monitor timer fires, check process status.

3465 NOT Feb 18 05:30:37.625520 (199:1272) restart_mgr-start the process monitor timer

3466 NOT Feb 18 05:30:48.850539 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3467 DEB Feb 18 05:30:52.765174 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3468 DEB Feb 18 05:30:55.214558 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3469 WRN Feb 18 05:30:55.214638 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3470 NOT Feb 18 05:30:55.214660 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3471 DEB Feb 18 05:31:37.625713 (199:1285) restart_mgr-monitor timer fires, check process status.

3472 NOT Feb 18 05:31:37.645989 (199:1285) restart_mgr-start the process monitor timer

3473 NOT Feb 18 05:31:48.856569 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3474 DEB Feb 18 05:31:52.777612 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3475 DEB Feb 18 05:31:55.214841 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3476 WRN Feb 18 05:31:55.214923 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3477 NOT Feb 18 05:31:55.214945 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3478 DEB Feb 18 05:32:37.646190 (199:1295) restart_mgr-monitor timer fires, check process status.

3479 NOT Feb 18 05:32:37.668184 (199:1295) restart_mgr-start the process monitor timer

3480 NOT Feb 18 05:32:48.862542 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3481 DEB Feb 18 05:32:52.789921 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3482 DEB Feb 18 05:32:55.215127 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3483 WRN Feb 18 05:32:55.215204 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3484 NOT Feb 18 05:32:55.215228 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3485 DEB Feb 18 05:33:37.668405 (199:1305) restart_mgr-monitor timer fires, check process status.

3486 NOT Feb 18 05:33:37.690842 (199:1305) restart_mgr-start the process monitor timer

3487 NOT Feb 18 05:33:48.868536 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3488 DEB Feb 18 05:33:52.801689 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3489 DEB Feb 18 05:33:55.215412 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3490 WRN Feb 18 05:33:55.215492 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3491 NOT Feb 18 05:33:55.215515 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3492 DEB Feb 18 05:34:37.691030 (199:1315) restart_mgr-monitor timer fires, check process status.

3493 NOT Feb 18 05:34:37.713433 (199:1315) restart_mgr-start the process monitor timer

3494 NOT Feb 18 05:34:48.877394 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3495 DEB Feb 18 05:34:52.813128 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3496 DEB Feb 18 05:34:55.215701 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3497 WRN Feb 18 05:34:55.215780 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3498 NOT Feb 18 05:34:55.215802 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3499 DEB Feb 18 05:35:37.713659 (199:1332) restart_mgr-monitor timer fires, check process status.

3500 NOT Feb 18 05:35:37.734941 (199:1332) restart_mgr-start the process monitor timer

3501 NOT Feb 18 05:35:48.880333 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3502 DEB Feb 18 05:35:52.825409 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3503 DEB Feb 18 05:35:55.215981 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3504 WRN Feb 18 05:35:55.216059 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3505 NOT Feb 18 05:35:55.216081 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3506 INF Feb 18 05:36:30.799247 kernel: [ 977.228546] recv ARP request when GARP enabled

3507 DEB Feb 18 05:36:37.735136 (199:1344) restart_mgr-monitor timer fires, check process status.

3508 NOT Feb 18 05:36:37.763658 (199:1344) restart_mgr-start the process monitor timer

3509 NOT Feb 18 05:36:48.886661 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3510 DEB Feb 18 05:36:52.837510 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3511 DEB Feb 18 05:36:55.216269 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3512 WRN Feb 18 05:36:55.216347 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3513 NOT Feb 18 05:36:55.216368 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3514 DEB Feb 18 05:37:37.763862 (199:1354) restart_mgr-monitor timer fires, check process status.

3515 NOT Feb 18 05:37:37.783643 (199:1354) restart_mgr-start the process monitor timer

3516 NOT Feb 18 05:37:48.892254 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3517 DEB Feb 18 05:37:52.849431 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3518 DEB Feb 18 05:37:55.216551 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3519 WRN Feb 18 05:37:55.216629 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3520 NOT Feb 18 05:37:55.216652 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3521 NOT Feb 18 05:37:56.953016 (748:922) JAVA-HTTP JNI| processRedirect: Redirecting to, /CGI/Java/Serviceability?adapter=device.statistics.device

3522 INF Feb 18 05:37:57.020617 (748:861) JAVA-MicroServletTask|cip.http.HttpMicroServletRequest:? - IN: getSession()

3523 INF Feb 18 05:37:57.276846 (748:861) JAVA-MicroServletTask|cip.http.HttpSession:? - IN: HttpSession()

3524 INF Feb 18 05:37:57.277270 (748:861) JAVA-MicroServletTask|cip.http.HttpSession:? - OUT: HttpSession()

3525 INF Feb 18 05:37:57.284970 (748:861) JAVA-MicroServletTask|MicroServletContainer:? - IN: insertSession()

3526 INF Feb 18 05:37:57.285525 (748:861) JAVA-MicroServletTask|MicroServletContainer:? - before session insertion

3527 INF Feb 18 05:37:57.285932 (748:861) JAVA-MicroServletTask|MicroServletContainer:? - OUT: insertSession()

3528 NOT Feb 18 05:37:57.473529 (748:846) JAVA-HTTP JNI| Java_cip_http_NativeHttpTask_updateServletRequest: conId=0, state=3, error=0, mimeType=0

3529 NOT Feb 18 05:37:57.473764 (748:920) JAVA-HTTP JNI| httpServerHandler: conId=0, pushStatus=3

3530 NOT Feb 18 05:37:57.473990 (748:920) JAVA-HTTP JNI| processFileResponse: Sending, fileName=/tmp/cache/PUSH_RESP_0_0.x to client with additional headers: Set-Cookie: C0=ID=aWciJ/9rCpIwa7VhexLosg==; path=/CGI/Java; HttpOnly; secure;^M

3531 NOT Feb 18 05:37:57.518422 (748:923) JAVA-HTTP JNI| processFileResponse: Sending, fileName=/tmp/cache/Logo.png to client with additional headers: (null)

3532 INF Feb 18 05:38:06.997597 (748:861) JAVA-MicroServletTask|cip.http.HttpMicroServletRequest:? - IN: getSession()

3533 INF Feb 18 05:38:06.998063 (748:861) JAVA-MicroServletTask|cip.http.HttpSession:? - IN: HttpSession()

3534 INF Feb 18 05:38:06.998334 (748:861) JAVA-MicroServletTask|cip.http.HttpSession:? - OUT: HttpSession()

3535 INF Feb 18 05:38:06.998432 (748:861) JAVA-MicroServletTask|MicroServletContainer:? - IN: insertSession()

3536 INF Feb 18 05:38:06.998525 (748:861) JAVA-MicroServletTask|MicroServletContainer:? - before session insertion

3537 INF Feb 18 05:38:06.998640 (748:861) JAVA-MicroServletTask|MicroServletContainer:? - OUT: insertSession()

3538 NOT Feb 18 05:38:07.093317 (748:846) JAVA-HTTP JNI| Java_cip_http_NativeHttpTask_updateServletRequest: conId=0, state=3, error=0, mimeType=0

3539 NOT Feb 18 05:38:07.093542 (748:921) JAVA-HTTP JNI| httpServerHandler: conId=0, pushStatus=3

3540 NOT Feb 18 05:38:07.093589 (748:921) JAVA-HTTP JNI| processFileResponse: Sending, fileName=/tmp/cache/PUSH_RESP_0_1.x to client with additional headers: Set-Cookie: C0=ID=4cz1oS70RkG53jXl/5gl+Q==; path=/CGI/Java; HttpOnly; secure;^M

3541 NOT Feb 18 05:38:07.147032 (748:922) JAVA-HTTP JNI| processFileResponse: Sending, fileName=/tmp/cache/Logo.png to client with additional headers: (null)

3542 NOT Feb 18 05:38:13.566333 (748:920) JAVA-HTTP JNI| processFileResponse: Sending, fileName=/tmp/cache/messages.0 to client with additional headers: (null)

3543 DEB Feb 18 05:38:37.783832 (199:1367) restart_mgr-monitor timer fires, check process status.

3544 NOT Feb 18 05:38:37.805477 (199:1367) restart_mgr-start the process monitor timer

3545 NOT Feb 18 05:38:48.901470 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3546 DEB Feb 18 05:38:52.860984 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3547 DEB Feb 18 05:38:55.216834 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3548 WRN Feb 18 05:38:55.216918 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3549 NOT Feb 18 05:38:55.216939 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3550 NOT Feb 18 05:39:16.162268 (748:923) JAVA-HTTP JNI| processFileResponse: Sending, fileName=/tmp/cache/messages.0 to client with additional headers: (null)






3 - Cisco Systems - # RELEASE Model=88xx Version=sip88xx.12-1-1SR1-4

[TZ=GMT+00:00

] Mon Feb 18 05:25:12 2019

=============================================================[V04][HW ver: V01 ]

[3]

3416 INF Feb 18 05:25:12.788364 syslogd forced rotation

3417 NOT Feb 18 05:25:12.789052 (317:317) sarchmon-/var/log/messages.3 not present

3418 NOT Feb 18 05:25:13.803860 (1092:1092) sarch: -Archiving syslogs to /cisco/logsave/main max=999

3419 NOT Feb 18 05:25:14.375374 (1128:1128) sarch: -dir size /cisco/logsave/main is 0

3420 NOT Feb 18 05:25:14.514818 (1139:1139) sarch: -trying to remove oldest file 20190114_211502.tar.gz

3421 NOT Feb 18 05:25:14.921194 (1153:1153) sarch: -dir size /cisco/logsave/main is 0

3422 NOT Feb 18 05:25:15.044966 (1161:1161) sarch: -trying to remove oldest file 20190114_221502.tar.gz

3423 NOT Feb 18 05:25:15.301787 (1175:1175) sarch: -dir size /cisco/logsave/main is 0

3424 NOT Feb 18 05:25:15.534070 (1183:1183) sarch: -trying to remove oldest file 20190114_231502.tar.gz

3425 NOT Feb 18 05:25:15.812902 (1198:1198) sarch: -dir size /cisco/logsave/main is 2072576

3426 NOT Feb 18 05:25:16.029343 (1199:1199) sarch: -archiving /tmp/20190218_052514.tar.gz

3427 DEB Feb 18 05:25:37.494810 (199:1206) restart_mgr-monitor timer fires, check process status.

3428 NOT Feb 18 05:25:37.517456 (199:1206) restart_mgr-start the process monitor timer

3429 NOT Feb 18 05:25:48.820868 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3430 DEB Feb 18 05:25:52.702394 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3431 DEB Feb 18 05:25:55.213068 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3432 WRN Feb 18 05:25:55.213187 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3433 NOT Feb 18 05:25:55.213213 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3434 DEB Feb 18 05:26:37.517882 (199:1218) restart_mgr-monitor timer fires, check process status.

3435 NOT Feb 18 05:26:37.537765 (199:1218) restart_mgr-start the process monitor timer

3436 NOT Feb 18 05:26:48.829680 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3437 DEB Feb 18 05:26:52.714739 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3438 DEB Feb 18 05:26:55.213403 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3439 WRN Feb 18 05:26:55.213483 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3440 NOT Feb 18 05:26:55.213505 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3441 DEB Feb 18 05:27:37.537965 (199:1228) restart_mgr-monitor timer fires, check process status.

3442 NOT Feb 18 05:27:37.559803 (199:1228) restart_mgr-start the process monitor timer

3443 NOT Feb 18 05:27:48.832636 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3444 DEB Feb 18 05:27:52.727432 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3445 DEB Feb 18 05:27:55.213686 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3446 WRN Feb 18 05:27:55.213766 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3447 NOT Feb 18 05:27:55.213790 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3448 DEB Feb 18 05:28:37.560026 (199:1238) restart_mgr-monitor timer fires, check process status.

3449 NOT Feb 18 05:28:37.581552 (199:1238) restart_mgr-start the process monitor timer

3450 NOT Feb 18 05:28:48.838668 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3451 DEB Feb 18 05:28:52.741015 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3452 DEB Feb 18 05:28:55.213975 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3453 WRN Feb 18 05:28:55.214051 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3454 NOT Feb 18 05:28:55.214075 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds

3455 DEB Feb 18 05:29:37.581743 (199:1248) restart_mgr-monitor timer fires, check process status.

3456 NOT Feb 18 05:29:37.602357 (199:1248) restart_mgr-start the process monitor timer

3457 NOT Feb 18 05:29:48.844592 (459:533) CDP-cdpRcvPkt(): deviceId is Switch

3458 DEB Feb 18 05:29:52.753639 (0:728) syslog-dbus_manager::Sleeping 60 seconds

3459 DEB Feb 18 05:29:55.214263 (743:743) sparkd-getStringProperty: read value for device.settings.fullyregistered: 0

3460 WRN Feb 18 05:29:55.214345 (743:743) sparkd-Phone is not registered - no further toggle checks are required

3461 NOT Feb 18 05:29:55.214368 (743:743) sparkd-Not ready to init sparkd - retrying in 60 seconds


Russell

[nagaraj789]

Hi,

As you say, phones are trying with internal ip address, try to change TFTP ip address manually and see if it works

[russjstewart]

Hi Nagaraj,
Thanks for taking the time to reply to my post. I think when the phone is trying the internal address it is part of the process to see if it needs to use the VPN or not.
What do you suggest changing the TFTP IP address to

Thanks

[dboggs]

Looks like an old post but I will reply in hopes it helps someone else....make sure you have the vpn profile setup in Call Manager - the phone will need to register internally first and then test from the Internet - validate all steps:

https://www.cisco.com/c/en/us/support/docs/security/anyconnect-secure-mobility-client/116162-trouble-anyconnect-vpn-phone-00.html#anc21