phoneDevSpecific returns PHONE_REPLY 0x90000014 INVALID PHONE STATE

mark.brezina · ‎10-28-2021

Hi, our product uses phoneDevSpecific to push phone execute requests to Cisco IP phones.

The product has been working great for 15+ years on CallManager 4.0 through 12.5 with 79xx series phones.

Since adding support for 88xx phones, we are frequently seeing PHONE_REPLY with dwParam2 = 0x90000014 (Invalid Phone State) reported after a push. The code checks that the phones are in Connected state by calling phoneGetStatus() prior to calling phoneDevSpecific(). The PHONE_REPLY with the error comes exactly 5 seconds after the call.

The error happens consistently with 8821, 8841 and 8861phones and Call Manager 12.5. The push notification typically goes through to the phone, even when the error is reported. The phones execute the push request, but this error is reported through TAPI and is logged in our system.

I've uploaded TSP logs that show 'link read time out' on a socket just prior to firing lResult=0x9000014. The sequence of calling phoneGetStatus() and phoneDevSpecific() starts at 06:45:59.918 in the log.

06:45:59.964 | TSPI_phoneDevSpecific() TSPI_phoneDevSpecific returns = 0x0001038B
06:45:59.964 |<--TSPI_phoneDevSpecific()
06:46:00.434 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:00.434 |<--CSelsiusTSPLink::getMessage()
06:46:00.434 |-->CSelsiusTSPLink::getMessage()
06:46:00.934 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:00.934 |<--CSelsiusTSPLink::getMessage()
06:46:00.934 |-->CSelsiusTSPLink::getMessage()
06:46:01.435 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:01.435 |<--CSelsiusTSPLink::getMessage()
06:46:01.435 |-->CSelsiusTSPLink::getMessage()
06:46:01.935 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:01.935 |<--CSelsiusTSPLink::getMessage()
06:46:01.935 |-->CSelsiusTSPLink::getMessage()
06:46:02.435 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:02.435 |<--CSelsiusTSPLink::getMessage()
06:46:02.435 |-->CSelsiusTSPLink::getMessage()
06:46:02.936 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:02.936 |<--CSelsiusTSPLink::getMessage()
06:46:02.936 |-->CSelsiusTSPLink::getMessage()
06:46:03.437 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:03.437 |<--CSelsiusTSPLink::getMessage()
06:46:03.437 |-->CSelsiusTSPLink::getMessage()
06:46:03.937 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:03.937 |<--CSelsiusTSPLink::getMessage()
06:46:03.937 |-->CSelsiusTSPLink::getMessage()
06:46:04.438 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:04.438 |<--CSelsiusTSPLink::getMessage()
06:46:04.438 |-->CSelsiusTSPLink::getMessage()
06:46:04.938 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=3128
06:46:04.938 |<--CSelsiusTSPLink::getMessage()

...

06:46:04.969 |-->CSelsiusTSP::FireAsyncCompletion()
06:46:04.969 | CSelsiusTSP::FireAsyncCompletion()
dwRequestID=0x0001038B
lResult=0x90000014
m_pfnCompletionProc=[0xD14B9F70]

Is a different call sequence needed for 88xx phones? Any help would be appreciated.

Thanks

dstaudt · ‎10-29-2021

Not aware of any differences that should be apparent for these phones. I strongly suspect we'll need to look at the detailed TAPI logs (and perhaps phone logs too): suggest opening a developer support ticket so we can investigate: https://developer.cisco.com/site/support/

Please include the TAPI logs, details of the scenario (device names/IPs, timestamps of test, etc.), and I might attach phone network capture logs (e.g. via Wireshark) as well.

mark.brezina · ‎10-29-2021

Thanks Dave, I'll get a support ticket created for this.