This document was generated from CDN thread
Created by: Christoph Mueller on 01-04-2011 08:56:43 AM
Hello,
we are experiencing problems with CTI Ports:
Our application accepts calls at a route point and redirects them to a free CTI port.
This works normally first, but after a hew hours or sometimes days, the CTI port (sometimes, not always) does not get the call and the caller gets the busy signal. In the tsp logs I found a strange "Faking disconnect"-event exactly at the times, the strange behaviour occurs. After resetting the TAPI lines, everything works fine, til the problem occurs again after a few hours.
Does anyone have any ideas?
Thanks a lot in advance
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::CallStateEvent() LineId:[0x00007798] RT-Lite :CallStateEvent:Is Consult Call RolledOver(Transfer and Conference): 0x00000000|<LVL:
etailed><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| DeviceStateIdleEvent::Trace
CtiDeviceHandle.callManagerId =8
CtiDeviceHandle.deviceId =0x000071B0|<LVL::Special><MASK::0200>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--DeviceStateIdleEvent::Trace |<LVL::Entry_exit><MASK::0200>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|-->CSelsiusTSPLine::FindCallBySCMHandle() LineId:[0x00007798] |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLink::getMessage() Read 40 bytes, message number is 0x000000ce|<LVL:etailed><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--CSelsiusTSPLink::getMessage() |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::FindCallBySCMHandle() LineId:[0x00007798] Found mapping for callHandle(0x086E6F6D) to call(0x01CB68C0)|<LVL:etailed><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--CSelsiusTSPLine::FindCallBySCMHandle() LineId:[0x00007798] |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::CallStateEvent() LineId:[0x00007798] Faking a Disconnect call state.|<LVL:etailed><MASK::0001>
Subject: Re: New Message from Christoph Mueller in Cisco TAPI (TAPI) - Cisco TAPI Qu
Replied by: Jun Xue on 01-04-2011 01:38:24 PM
Can you please check the following
1. Make sure the CTI port is registered
2. Make sure TAPI application is receiving new call event on the CTI port
3. Make sure TAPI application is accept or answering call within 4 seconds.
Not sure what you meant by "reseting TAPI lines". Did you restart TAPI
application or close lines and reopen? Based on your trace snip, seems to me
that CTI port is getting call event, so I suspect the call was not accepted
or answered within 4 sec from application.
From: Cisco Developer Community Forums <cdicuser@developer.cisco.com>
Reply-To: "cdicuser@developer.cisco.com" <cdicuser@developer.cisco.com>
Date: Fri, 1 Apr 2011 08:56:43 -0400 (EDT)
To: "cdicuser@developer.cisco.com" <cdicuser@developer.cisco.com>
Subject: New Message from Christoph Mueller in Cisco TAPI (TAPI) - Cisco
TAPI Questions: CTI Port "Faking Disconnect"
Christoph Mueller has created a new message in the forum "Cisco TAPI
Questions":
--------------------------------------------------------------
Hello,
we are experiencing problems with CTI Ports:
Our application accepts calls at a route point and redirects them to a free
CTI port.
This works normally first, but after a hew hours or sometimes days, the CTI
port (sometimes, not always) does not get the call and the caller gets the
busy signal. In the tsp logs I found a strange "Faking disconnect"-event
exactly at the times, the strange behaviour occurs. After resetting the TAPI
lines, everything works fine, til the problem occurs again after a few
hours.
Does anyone have any ideas?
Thanks a lot in advance
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::CallStateEvent()
LineId:[0x00007798] RT-Lite :CallStateEvent:Is Consult Call
RolledOver(Transfer and Conference): 0x00000000|<LVL:etailed><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| DeviceStateIdleEvent::Trace
CtiDeviceHandle.callManagerId =8
CtiDeviceHandle.deviceId =0x000071B0|<LVL::Special><MASK::0200>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--DeviceStateIdleEvent::Trace
|<LVL::Entry_exit><MASK::0200>
04/01/2011 14:21:00.973
CiscoTSP001.tsp|-->CSelsiusTSPLine::FindCallBySCMHandle()
LineId:[0x00007798] |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLink::getMessage()
Read 40 bytes, message number is 0x000000ce|<LVL:etailed><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--CSelsiusTSPLink::getMessage()
|<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|
CSelsiusTSPLine::FindCallBySCMHandle() LineId:[0x00007798] Found mapping for
callHandle(0x086E6F6D) to call(0x01CB68C0)|<LVL:etailed><MASK::0001>
04/01/2011 14:21:00.973
CiscoTSP001.tsp|<--CSelsiusTSPLine::FindCallBySCMHandle()
LineId:[0x00007798] |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::CallStateEvent()
LineId:[0x00007798] Faking a Disconnect call
state.|<LVL:etailed><MASK::0001>
--
To respond to this post, please click the following link:
<http://developer.cisco.com/web/tapi/forums/-/message_boards/view_message/34
16269>
or simply reply to this email.
Subject: RE: CTI Port "Faking Disconnect"
Replied by: Christoph Mueller on 04-04-2011 04:37:18 AM
Thank you for your repsonse.
The CTI ports are registered and waiting for call events. The do not fail everytime to notice a new incoming call, just sometimes. It gets worse the longer the app is running. After closing our TAPI application (including closing the TAPI lines) and restarting the app (and opening the lines again), everything seems to be working fine. I will check the 4 seconds, but from our application logs, it seems that the CTI ports just don't receive the call.
Subject: RE: CTI Port "Faking Disconnect"
Replied by: Christopher Cunningham on 24-10-2013 07:32:41 PM
I am having the same/similar issue.
The problem only occurs when using the Cisco softphone. 8.6.3.0
The TSP is updating when I log in and out of the phone however I cannot make a call through the phone using the Windows Dialer.
Our logs are showing:
:10:26.474 | TSPI_phoneGetDevCaps() TSPI_phoneGetDevCaps returns = 0x00000000
13:10:26.474 |<--TSPI_phoneGetDevCaps()
13:10:26.859 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:26.859 |<--CSelsiusTSPLink::getMessage()
13:10:26.859 |-->CSelsiusTSPLink::getMessage()
13:10:27.859 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:27.859 |<--CSelsiusTSPLink::getMessage()
13:10:27.859 |-->CSelsiusTSPLink::getMessage()
13:10:28.859 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:28.859 |<--CSelsiusTSPLink::getMessage()
13:10:28.859 |-->CSelsiusTSPLink::getMessage()
13:10:29.859 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:29.859 |<--CSelsiusTSPLink::getMessage()
13:10:29.859 |-->CSelsiusTSPLink::getMessage()
13:10:30.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:30.860 |<--CSelsiusTSPLink::getMessage()
13:10:30.860 |-->CSelsiusTSPLink::getMessage()
13:10:31.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:31.860 |<--CSelsiusTSPLink::getMessage()
13:10:31.860 |-->CSelsiusTSPLink::getMessage()
13:10:32.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:32.860 |<--CSelsiusTSPLink::getMessage()
13:10:32.860 |-->CSelsiusTSPLink::getMessage()
13:10:33.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:33.860 |<--CSelsiusTSPLink::getMessage()
13:10:33.860 |-->CSelsiusTSPLink::getMessage()
13:10:34.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:34.860 |<--CSelsiusTSPLink::getMessage()
13:10:34.860 |-->CSelsiusTSPLink::getMessage()
13:10:35.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:35.860 |<--CSelsiusTSPLink::getMessage()
13:10:35.860 |-->CSelsiusTSPLink::getMessage()
13:10:36.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:36.860 |<--CSelsiusTSPLink::getMessage()
13:10:36.860 |-->CSelsiusTSPLink::getMessage()
13:10:37.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:37.860 |<--CSelsiusTSPLink::getMessage()
13:10:37.860 |-->CSelsiusTSPLink::getMessage()
13:10:38.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:38.860 |<--CSelsiusTSPLink::getMessage()
13:10:38.860 |-->CSelsiusTSPLink::getMessage()
13:10:39.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:39.860 |<--CSelsiusTSPLink::getMessage()
13:10:39.860 |-->CSelsiusTSPLink::getMessage()
13:10:40.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:40.861 |<--CSelsiusTSPLink::getMessage()
13:10:40.861 |-->CSelsiusTSPLink::getMessage()
13:10:41.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:41.861 |<--CSelsiusTSPLink::getMessage()
13:10:41.861 |-->CSelsiusTSPLink::getMessage()
13:10:42.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:42.861 |<--CSelsiusTSPLink::getMessage()
13:10:42.861 |-->CSelsiusTSPLink::getMessage()
13:10:43.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:43.861 |<--CSelsiusTSPLink::getMessage()
13:10:43.861 |-->CSelsiusTSPLink::getMessage()
13:10:44.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:44.861 |<--CSelsiusTSPLink::getMessage()
13:10:44.861 |-->CSelsiusTSPLink::getMessage()
13:10:45.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:45.861 |<--CSelsiusTSPLink::getMessage()
13:10:45.861 |-->CSelsiusTSPLink::getMessage()
13:10:46.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:46.861 |<--CSelsiusTSPLink::getMessage()
13:10:46.861 |-->CSelsiusTSPLink::getMessage()
13:10:47.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:47.861 |<--CSelsiusTSPLink::getMessage()
13:10:47.861 |-->CSelsiusTSPLink::getMessage()
13:10:48.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:48.861 |<--CSelsiusTSPLink::getMessage()
13:10:48.861 |-->CSelsiusTSPLink::getMessage()
13:10:49.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:49.861 |<--CSelsiusTSPLink::getMessage()
13:10:49.861 |-->CSelsiusTSPLink::getMessage()
13:10:50.315 | CCtiHeartbeat::heartbeatLoop() Time-out. wait() return=-1 waitTimeout=30000
13:10:50.315 | CCtiHeartbeat::heartbeatLoop() Sending heartbeat message
13:10:50.315 |-->CCtiInterface::SendHeartbeat()
13:10:50.315 |-->CCtiInterface::sendCtiMessage()
13:10:50.315 |-->SendMessage()
13:10:50.315 |-->Heartbeat::qbeTraceOut
13:10:50.315 |<--Heartbeat::qbeTraceOut
aswell as:
TSPI_providerShutdown() After GlobalTSP->TSPI_providerShutdown()
Here is an example when I try to make a call out using Windows Dialer:
1:09:40.051 |<--LineGetInfoRequest::Trace
11:09:40.051 | SendMessage() sent message number 0x0000002d, sequence number 0x0000000e, 44 bytes
11:09:40.051 |<--SendMessage()
11:09:40.051 |<--CCtiInterface::sendCtiMessage()
11:09:40.051 |<--CCtiInterface::sendAsyncCtiRequest(): ctiRequestId=14 tId=0x00000F08
11:09:40.051 |<--CCtiInterface::sendAsynchronousCtiLineRequest(): appRequestId=0xFFFFFFFF
11:09:40.051 |<--CCtiInterface::sendAsynchronousCtiLineRequest(NoSavedData)
11:09:40.051 |<--CCtiInterface::CtiLineLineInfo()
11:09:40.051 |<--CSelsiusTSPLine::GetInfoRequest() [0x00001A36]
11:09:40.051 | SelsiusTSP:
rocessWorkerQueueUntilEmpty() MX_DEBUG_MB: deleting object(01506BB0)
11:09:40.051 |<--SelsiusTSP:rocessWorkerQueueUntilEmpty()
11:09:40.051 | SelsiusTSP::WorkerLoop() worker thread waiting for signal from main thread that there is a request
11:09:40.051 |-->TSPI_lineMakeCall()
11:09:40.051 | TSPI_lineMakeCall()
dwRequestID =0x00010399
hdLine =0x01434E58
htCall =0x00010388
lphdCall =0x02616260
DestAddress =T1021xxxxxxxx
dwCountryCode =0x00000000
lpCallParams =0x02616160
11:09:40.051 |-->SelsiusTSP::TSPI_lineMakeCall(0x01434E58)
11:09:40.051 |-->CSelsiusTSPLineList::IsValidTapiLineHandle()
11:09:40.051 | CSelsiusTSPLineList::IsValidTapiLineHandle() Found mapping for line(0x01434E58) to lineHandle(0x00001A36)
11:09:40.051 |<--CSelsiusTSPLineList::IsValidTapiLineHandle()
11:09:40.051 |-->CSelsiusTSPLine::MakeCall() line id=0x00001A36
11:09:40.051 |-->CSelsiusTSPLine:rescanDestinationAddress()
11:09:40.051 |<--CSelsiusTSPLine:rescanDestinationAddress()
11:09:40.051 |-->CCtiInterface::SendAllocateGlobalCallHandleRequest()
11:09:40.051 |-->CCtiInterface::sendSynchronousCtiRequest(): tId=0x00000B80
11:09:40.051 |-->CCtiRequestMap::add()
11:09:40.051 | CCtiRequestMap::add() Adding map entry for sequenceNumber(0x0000000F) to responseObject(0x0142DC68)
11:09:40.051 |<--CCtiRequestMap::add()
11:09:40.051 |-->CCtiInterface::sendCtiMessage()
11:09:40.051 |-->SendMessage()
11:09:40.051 |-->ProviderAllocateGlobalCallHandleRequest::Trace
11:09:40.051 | ProviderAllocateGlobalCallHandleRequest::Trace :dwSequenceNumber = 0x0000000F
11:09:40.051 | ProviderAllocateGlobalCallHandleRequest::Trace
dummyHeader.dwLen =28
dummyHeader.dwType =0
dwMagicCookie =0xFFFFDDDD
dwProtocolVersion =0x000D0001
dwPDUNumber =11
dwHeaderSize =32
dwFixedSize =4
dwVariableSize =0
11:09:40.051 |<--ProviderAllocateGlobalCallHandleRequest::Trace
11:09:40.051 | SendMessage() sent message number 0x0000000b, sequence number 0x0000000f, 36 bytes
11:09:40.051 |<--SendMessage()
11:09:40.051 |<--CCtiInterface::sendCtiMessage()
11:09:40.051 |-->CSynchResponseObject::wait()
11:09:40.051 | CSynchResponseObject::wait() Waiting to receive synchronous response or timeout 15000
11:09:40.065 | CSelsiusTSPLink::getMessage() QBE message header: {{0x00000028, 0x00000000}, 0xFFFFDDDD, 0x000D0001, 0x0000000C, 0x00000020, 0x00000010, 0x00000000}
11:09:40.065 | CSelsiusTSPLink::getMessage() Read 48 bytes, message number is 0x0000000c
11:09:40.065 |<--CSelsiusTSPLink::getMessage()
11:09:40.065 | CCtiReceiver::receiveLoop() Received message. PDU# 0x0000000C(12)
11:09:40.065 |-->ProviderAllocateGlobalCallHandleResponse::qbeTrace
11:09:40.065 | ProviderAllocateGlobalCallHandleResponse::qbeTrace seq# =0x0000000F result =0x00000000
11:09:40.065 | ProviderAllocateGlobalCallHandleResponse::qbeTrace {{0x00000028, 0x00000000}, 0xFFFFDDDD, 0x000D0001, 0x0000000C, 0x00000020, 0x00000010, 0x00000000}
11:09:40.065 | ProviderAllocateGlobalCallHandleResponse::qbeTrace
globalCallHandle.callManagerId =3
globalCallHandle.callLegId =0x00002065
11:09:40.065 |<--ProviderAllocateGlobalCallHandleResponse::qbeTrace
11:09:40.065 |-->CCtiInterface:rocessResponse()
11:09:40.065 | CCtiInterface:rocessResponse() Found mapping seq#: 0x0000000F to responseObject: 0x0142DC68
11:09:40.065 |-->CSynchResponseObject::notify()
11:09:40.065 |<--CSynchResponseObject::notify()
11:09:40.065 |<--CCtiInterface:rocessResponse()
11:09:40.065 | CCtiReceiver::receiveLoop() Server heartbeat: 30. Waiting 60 seconds for a message (countdown: 60).
11:09:40.066 |-->CSelsiusTSPLink::getMessage()
11:09:40.066 |<--CSynchResponseObject::wait()
11:09:40.066 |<--CCtiInterface::sendSynchronousCtiRequest(): tId=0x00000B80
11:09:40.066 |-->CCtiInterface:rocessProviderAllocateGlobalCallHandleResponse()
11:09:40.066 | CCtiInterface:rocessProviderAllocateGlobalCallHandleResponse() Result of Provider Allocate Global Call Handle request is 0
11:09:40.066 |<--CCtiInterface:rocessProviderAllocateGlobalCallHandleResponse()
11:09:40.066 |<--CCtiInterface::SendAllocateGlobalCallHandleRequest()
11:09:40.066 | CSelsiusTSPLine::MakeCall() line id=0x00001A36 Allocated a global call handle for initiating a call: call manager id=0x3, global call id=0x2065
11:09:40.066 |-->CSelsiusTSPCallList::GetNewCall()
11:09:40.066 |-->CTspCallInfo::CTspCallInfo()
11:09:40.066 |<--CTspCallInfo::CTspCallInfo()
11:09:40.066 |-->CSelsiusTSPCall::CSelsiusTSPCall()
11:09:40.066 | CSelsiusTSPCall::CSelsiusTSPCall() setting SecureMemMgr = 0x015016F8
11:09:40.066 | CSelsiusTSPCall::CSelsiusTSPCall() setting BlockDynamicDataflag [0]
11:09:40.066 | CSelsiusTSPCall::CSelsiusTSPCall() setting UseModifiedDNForExternalParty flag [0]
11:09:40.066 |<--CSelsiusTSPCall::CSelsiusTSPCall()
11:09:40.066 | CSelsiusTSPCallList::GetNewCall() callIndex=0x00000000 permLineId=0x80361A01 call=0x02507DB0 m_Call=0x02507DB0 m_LastNewCallIndex=0x00000000
11:09:40.066 |<--CSelsiusTSPCallList::GetNewCall()
11:09:40.066 |-->CScopedCriticalSection::CScopedCriticalSection() [0x01435158]
11:09:40.066 |<--CScopedCriticalSection::CScopedCriticalSection() [0x01435158]
11:09:40.066 |-->CCtiInterface::CtiLineCallInitiate()
11:09:40.066 |-->CQBE_Builder::qbePut:QBE_ByteArray()
11:09:40.066 | CQBE_Builder::qbePut:QBE_ByteArray() else case (either pArray or ArraySize are NULL)
11:09:40.066 |<--CQBE_Builder::qbePut:QBE_ByteArray()
11:09:40.066 |-->CCtiInterface::sendAsynchronousCtiLineRequest(): appRequestId=0x00010399
11:09:40.066 |-->CCtiInterface::sendAsyncCtiRequest(): ctiRequestId=16 tId=0x00000B80
11:09:40.066 |-->CCtiRequestMap::add()
11:09:40.066 | CCtiRequestMap::add() Adding map entry for sequenceNumber(0x00000010) to responseObject(0x014FF000)
11:09:40.066 |<--CCtiRequestMap::add()
11:09:40.066 |-->CCtiInterface::sendCtiMessage()
11:09:40.066 |-->SendMessage()
11:09:40.066 |-->LineCallInitiateRequest::Trace
11:09:40.066 | LineCallInitiateRequest::Trace :dwSequenceNumber = 0x00000010
11:09:40.066 | LineCallInitiateRequest::Trace
dummyHeader.dwLen =101
dummyHeader.dwType =0
dwMagicCookie =0xFFFFDDDD
dwProtocolVersion =0x000D0001
dwPDUNumber =43
dwHeaderSize =32
dwFixedSize =60
dwVariableSize =17
11:09:40.066 | LineCallInitiateRequest::Trace
CtiLineHandle.callManagerId =6
CtiLineHandle.lineId =0x00001A36
11:09:40.066 | LineCallInitiateRequest::Trace
globalCallHandle.callManagerId =3
globalCallHandle.callLegId =0x00002065
11:09:40.066 | LineCallInitiateRequest::Trace
dwCallingAddressOffset =0x0000005C
dwCallingAddressSize =5
CallingAddress =9137
dwDestAddressOffset =0x00000061
dwDestAddressSize =12
DestAddress =10211478583
dwMediaDeviceNameOffset =0x00000000
dwMediaDeviceNameSize =0
MediaDeviceName =
dwMediaResourceId =0
11:09:40.066 | LineCallInitiateRequest::Trace
UserData:size = 0
11:09:40.066 |<--LineCallInitiateRequest::Trace
11:09:40.066 | SendMessage() sent message number 0x0000002b, sequence number 0x00000010, 109 bytes
11:09:40.066 |<--SendMessage()
11:09:40.066 |<--CCtiInterface::sendCtiMessage()
11:09:40.066 |<--CCtiInterface::sendAsyncCtiRequest(): ctiRequestId=16 tId=0x00000B80
11:09:40.066 |<--CCtiInterface::sendAsynchronousCtiLineRequest(): appRequestId=0x00010399
11:09:40.066 |<--CCtiInterface::CtiLineCallInitiate()
11:09:40.066 |-->CSelsiusTSPLine::AddRequestID() [0x00001A36]
11:09:40.066 |<--CSelsiusTSPLine::AddRequestID() [0x00001A36]
11:09:40.066 |-->CSelsiusTSPCall::SetNoAnswerTimeout() 0x00000000
11:09:40.066 |<--CSelsiusTSPCall::SetNoAnswerTimeout() 0x00000000
11:09:40.066 |-->CScopedCriticalSection::~CScopedCriticalSection() [0x01435158]
11:09:40.066 |<--CScopedCriticalSection::~CScopedCriticalSection() [0x01435158]
11:09:40.066 |<--CSelsiusTSPLine::MakeCall() line id=0x00001A36
11:09:40.066 |<--SelsiusTSP::TSPI_lineMakeCall(0x01434E58)
11:09:40.066 | TSPI_lineMakeCall() TSPI_lineMakeCall returns = 0x00010399
11:09:40.066 |<--TSPI_lineMakeCall()
11:09:41.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:41.066 |<--CSelsiusTSPLink::getMessage()
11:09:41.066 |-->CSelsiusTSPLink::getMessage()
11:09:42.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:42.066 |<--CSelsiusTSPLink::getMessage()
11:09:42.066 |-->CSelsiusTSPLink::getMessage()
11:09:43.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:43.066 |<--CSelsiusTSPLink::getMessage()
11:09:43.066 |-->CSelsiusTSPLink::getMessage()
11:09:44.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:44.066 |<--CSelsiusTSPLink::getMessage()
11:09:44.066 |-->CSelsiusTSPLink::getMessage()
11:09:45.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:45.066 |<--CSelsiusTSPLink::getMessage()
11:09:45.066 |-->CSelsiusTSPLink::getMessage()
11:09:45.066 | CSelsiusTSPLink::getMessage() QBE message header: {{0x00000046, 0x00000000}, 0xFFFFDDDD, 0x000D0001, 0x00000000, 0x00000020, 0x00000010, 0x0000001E}
11:09:45.066 | CSelsiusTSPLink::getMessage() Read 78 bytes, message number is 0x00000000
11:09:45.066 |<--CSelsiusTSPLink::getMessage()
11:09:45.066 | CCtiReceiver::receiveLoop() Received message. PDU# 0x00000000(0)
11:09:45.066 |-->FailureResponse::qbeTrace
11:09:45.066 | FailureResponse::qbeTrace seq# =0x0000000E result =0x8CCC0001
11:09:45.066 | FailureResponse::qbeTrace {{0x00000046, 0x00000000}, 0xFFFFDDDD, 0x000D0001, 0x00000000, 0x00000020, 0x00000010, 0x0000001E}
11:09:45.066 | FailureResponse::qbeTrace
dwResult =0x8CCC0001
Description : {0x00000030, 30, Line get info request failure }
At times the tsp doesn't update with changes and only after kiling the tapi srvc will updates start showing again.
Created by: Christoph Mueller on 01-04-2011 08:56:43 AM
Hello,
we are experiencing problems with CTI Ports:
Our application accepts calls at a route point and redirects them to a free CTI port.
This works normally first, but after a hew hours or sometimes days, the CTI port (sometimes, not always) does not get the call and the caller gets the busy signal. In the tsp logs I found a strange "Faking disconnect"-event exactly at the times, the strange behaviour occurs. After resetting the TAPI lines, everything works fine, til the problem occurs again after a few hours.
Does anyone have any ideas?
Thanks a lot in advance
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::CallStateEvent() LineId:[0x00007798] RT-Lite :CallStateEvent:Is Consult Call RolledOver(Transfer and Conference): 0x00000000|<LVL:
etailed><MASK::0001>04/01/2011 14:21:00.973 CiscoTSP001.tsp| DeviceStateIdleEvent::Trace
CtiDeviceHandle.callManagerId =8
CtiDeviceHandle.deviceId =0x000071B0|<LVL::Special><MASK::0200>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--DeviceStateIdleEvent::Trace |<LVL::Entry_exit><MASK::0200>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|-->CSelsiusTSPLine::FindCallBySCMHandle() LineId:[0x00007798] |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLink::getMessage() Read 40 bytes, message number is 0x000000ce|<LVL:
etailed><MASK::0001>04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--CSelsiusTSPLink::getMessage() |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::FindCallBySCMHandle() LineId:[0x00007798] Found mapping for callHandle(0x086E6F6D) to call(0x01CB68C0)|<LVL:
etailed><MASK::0001>04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--CSelsiusTSPLine::FindCallBySCMHandle() LineId:[0x00007798] |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::CallStateEvent() LineId:[0x00007798] Faking a Disconnect call state.|<LVL:
etailed><MASK::0001>Subject: Re: New Message from Christoph Mueller in Cisco TAPI (TAPI) - Cisco TAPI Qu
Replied by: Jun Xue on 01-04-2011 01:38:24 PM
Can you please check the following
1. Make sure the CTI port is registered
2. Make sure TAPI application is receiving new call event on the CTI port
3. Make sure TAPI application is accept or answering call within 4 seconds.
Not sure what you meant by "reseting TAPI lines". Did you restart TAPI
application or close lines and reopen? Based on your trace snip, seems to me
that CTI port is getting call event, so I suspect the call was not accepted
or answered within 4 sec from application.
From: Cisco Developer Community Forums <cdicuser@developer.cisco.com>
Reply-To: "cdicuser@developer.cisco.com" <cdicuser@developer.cisco.com>
Date: Fri, 1 Apr 2011 08:56:43 -0400 (EDT)
To: "cdicuser@developer.cisco.com" <cdicuser@developer.cisco.com>
Subject: New Message from Christoph Mueller in Cisco TAPI (TAPI) - Cisco
TAPI Questions: CTI Port "Faking Disconnect"
Christoph Mueller has created a new message in the forum "Cisco TAPI
Questions":
--------------------------------------------------------------
Hello,
we are experiencing problems with CTI Ports:
Our application accepts calls at a route point and redirects them to a free
CTI port.
This works normally first, but after a hew hours or sometimes days, the CTI
port (sometimes, not always) does not get the call and the caller gets the
busy signal. In the tsp logs I found a strange "Faking disconnect"-event
exactly at the times, the strange behaviour occurs. After resetting the TAPI
lines, everything works fine, til the problem occurs again after a few
hours.
Does anyone have any ideas?
Thanks a lot in advance
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::CallStateEvent()
LineId:[0x00007798] RT-Lite :CallStateEvent:Is Consult Call
RolledOver(Transfer and Conference): 0x00000000|<LVL:etailed><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| DeviceStateIdleEvent::Trace
CtiDeviceHandle.callManagerId =8
CtiDeviceHandle.deviceId =0x000071B0|<LVL::Special><MASK::0200>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--DeviceStateIdleEvent::Trace
|<LVL::Entry_exit><MASK::0200>
04/01/2011 14:21:00.973
CiscoTSP001.tsp|-->CSelsiusTSPLine::FindCallBySCMHandle()
LineId:[0x00007798] |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLink::getMessage()
Read 40 bytes, message number is 0x000000ce|<LVL:etailed><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|<--CSelsiusTSPLink::getMessage()
|<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp|
CSelsiusTSPLine::FindCallBySCMHandle() LineId:[0x00007798] Found mapping for
callHandle(0x086E6F6D) to call(0x01CB68C0)|<LVL:etailed><MASK::0001>
04/01/2011 14:21:00.973
CiscoTSP001.tsp|<--CSelsiusTSPLine::FindCallBySCMHandle()
LineId:[0x00007798] |<LVL::Entry_exit><MASK::0001>
04/01/2011 14:21:00.973 CiscoTSP001.tsp| CSelsiusTSPLine::CallStateEvent()
LineId:[0x00007798] Faking a Disconnect call
state.|<LVL:etailed><MASK::0001>
--
To respond to this post, please click the following link:
<http://developer.cisco.com/web/tapi/forums/-/message_boards/view_message/34
16269>
or simply reply to this email.
Subject: RE: CTI Port "Faking Disconnect"
Replied by: Christoph Mueller on 04-04-2011 04:37:18 AM
Thank you for your repsonse.
The CTI ports are registered and waiting for call events. The do not fail everytime to notice a new incoming call, just sometimes. It gets worse the longer the app is running. After closing our TAPI application (including closing the TAPI lines) and restarting the app (and opening the lines again), everything seems to be working fine. I will check the 4 seconds, but from our application logs, it seems that the CTI ports just don't receive the call.
Subject: RE: CTI Port "Faking Disconnect"
Replied by: Christopher Cunningham on 24-10-2013 07:32:41 PM
I am having the same/similar issue.
The problem only occurs when using the Cisco softphone. 8.6.3.0
The TSP is updating when I log in and out of the phone however I cannot make a call through the phone using the Windows Dialer.
Our logs are showing:
:10:26.474 | TSPI_phoneGetDevCaps() TSPI_phoneGetDevCaps returns = 0x00000000
13:10:26.474 |<--TSPI_phoneGetDevCaps()
13:10:26.859 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:26.859 |<--CSelsiusTSPLink::getMessage()
13:10:26.859 |-->CSelsiusTSPLink::getMessage()
13:10:27.859 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:27.859 |<--CSelsiusTSPLink::getMessage()
13:10:27.859 |-->CSelsiusTSPLink::getMessage()
13:10:28.859 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:28.859 |<--CSelsiusTSPLink::getMessage()
13:10:28.859 |-->CSelsiusTSPLink::getMessage()
13:10:29.859 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:29.859 |<--CSelsiusTSPLink::getMessage()
13:10:29.859 |-->CSelsiusTSPLink::getMessage()
13:10:30.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:30.860 |<--CSelsiusTSPLink::getMessage()
13:10:30.860 |-->CSelsiusTSPLink::getMessage()
13:10:31.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:31.860 |<--CSelsiusTSPLink::getMessage()
13:10:31.860 |-->CSelsiusTSPLink::getMessage()
13:10:32.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:32.860 |<--CSelsiusTSPLink::getMessage()
13:10:32.860 |-->CSelsiusTSPLink::getMessage()
13:10:33.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:33.860 |<--CSelsiusTSPLink::getMessage()
13:10:33.860 |-->CSelsiusTSPLink::getMessage()
13:10:34.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:34.860 |<--CSelsiusTSPLink::getMessage()
13:10:34.860 |-->CSelsiusTSPLink::getMessage()
13:10:35.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:35.860 |<--CSelsiusTSPLink::getMessage()
13:10:35.860 |-->CSelsiusTSPLink::getMessage()
13:10:36.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:36.860 |<--CSelsiusTSPLink::getMessage()
13:10:36.860 |-->CSelsiusTSPLink::getMessage()
13:10:37.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:37.860 |<--CSelsiusTSPLink::getMessage()
13:10:37.860 |-->CSelsiusTSPLink::getMessage()
13:10:38.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:38.860 |<--CSelsiusTSPLink::getMessage()
13:10:38.860 |-->CSelsiusTSPLink::getMessage()
13:10:39.860 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:39.860 |<--CSelsiusTSPLink::getMessage()
13:10:39.860 |-->CSelsiusTSPLink::getMessage()
13:10:40.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:40.861 |<--CSelsiusTSPLink::getMessage()
13:10:40.861 |-->CSelsiusTSPLink::getMessage()
13:10:41.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:41.861 |<--CSelsiusTSPLink::getMessage()
13:10:41.861 |-->CSelsiusTSPLink::getMessage()
13:10:42.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:42.861 |<--CSelsiusTSPLink::getMessage()
13:10:42.861 |-->CSelsiusTSPLink::getMessage()
13:10:43.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:43.861 |<--CSelsiusTSPLink::getMessage()
13:10:43.861 |-->CSelsiusTSPLink::getMessage()
13:10:44.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:44.861 |<--CSelsiusTSPLink::getMessage()
13:10:44.861 |-->CSelsiusTSPLink::getMessage()
13:10:45.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:45.861 |<--CSelsiusTSPLink::getMessage()
13:10:45.861 |-->CSelsiusTSPLink::getMessage()
13:10:46.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:46.861 |<--CSelsiusTSPLink::getMessage()
13:10:46.861 |-->CSelsiusTSPLink::getMessage()
13:10:47.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:47.861 |<--CSelsiusTSPLink::getMessage()
13:10:47.861 |-->CSelsiusTSPLink::getMessage()
13:10:48.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:48.861 |<--CSelsiusTSPLink::getMessage()
13:10:48.861 |-->CSelsiusTSPLink::getMessage()
13:10:49.861 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1348
13:10:49.861 |<--CSelsiusTSPLink::getMessage()
13:10:49.861 |-->CSelsiusTSPLink::getMessage()
13:10:50.315 | CCtiHeartbeat::heartbeatLoop() Time-out. wait() return=-1 waitTimeout=30000
13:10:50.315 | CCtiHeartbeat::heartbeatLoop() Sending heartbeat message
13:10:50.315 |-->CCtiInterface::SendHeartbeat()
13:10:50.315 |-->CCtiInterface::sendCtiMessage()
13:10:50.315 |-->SendMessage()
13:10:50.315 |-->Heartbeat::qbeTraceOut
13:10:50.315 |<--Heartbeat::qbeTraceOut
aswell as:
TSPI_providerShutdown() After GlobalTSP->TSPI_providerShutdown()
Here is an example when I try to make a call out using Windows Dialer:
1:09:40.051 |<--LineGetInfoRequest::Trace
11:09:40.051 | SendMessage() sent message number 0x0000002d, sequence number 0x0000000e, 44 bytes
11:09:40.051 |<--SendMessage()
11:09:40.051 |<--CCtiInterface::sendCtiMessage()
11:09:40.051 |<--CCtiInterface::sendAsyncCtiRequest(): ctiRequestId=14 tId=0x00000F08
11:09:40.051 |<--CCtiInterface::sendAsynchronousCtiLineRequest(): appRequestId=0xFFFFFFFF
11:09:40.051 |<--CCtiInterface::sendAsynchronousCtiLineRequest(NoSavedData)
11:09:40.051 |<--CCtiInterface::CtiLineLineInfo()
11:09:40.051 |<--CSelsiusTSPLine::GetInfoRequest() [0x00001A36]
11:09:40.051 | SelsiusTSP:
rocessWorkerQueueUntilEmpty() MX_DEBUG_MB: deleting object(01506BB0)11:09:40.051 |<--SelsiusTSP:
rocessWorkerQueueUntilEmpty() 11:09:40.051 | SelsiusTSP::WorkerLoop() worker thread waiting for signal from main thread that there is a request
11:09:40.051 |-->TSPI_lineMakeCall()
11:09:40.051 | TSPI_lineMakeCall()
dwRequestID =0x00010399
hdLine =0x01434E58
htCall =0x00010388
lphdCall =0x02616260
DestAddress =T1021xxxxxxxx
dwCountryCode =0x00000000
lpCallParams =0x02616160
11:09:40.051 |-->SelsiusTSP::TSPI_lineMakeCall(0x01434E58)
11:09:40.051 |-->CSelsiusTSPLineList::IsValidTapiLineHandle()
11:09:40.051 | CSelsiusTSPLineList::IsValidTapiLineHandle() Found mapping for line(0x01434E58) to lineHandle(0x00001A36)
11:09:40.051 |<--CSelsiusTSPLineList::IsValidTapiLineHandle()
11:09:40.051 |-->CSelsiusTSPLine::MakeCall() line id=0x00001A36
11:09:40.051 |-->CSelsiusTSPLine:
rescanDestinationAddress() 11:09:40.051 |<--CSelsiusTSPLine:
rescanDestinationAddress() 11:09:40.051 |-->CCtiInterface::SendAllocateGlobalCallHandleRequest()
11:09:40.051 |-->CCtiInterface::sendSynchronousCtiRequest(): tId=0x00000B80
11:09:40.051 |-->CCtiRequestMap::add()
11:09:40.051 | CCtiRequestMap::add() Adding map entry for sequenceNumber(0x0000000F) to responseObject(0x0142DC68)
11:09:40.051 |<--CCtiRequestMap::add()
11:09:40.051 |-->CCtiInterface::sendCtiMessage()
11:09:40.051 |-->SendMessage()
11:09:40.051 |-->ProviderAllocateGlobalCallHandleRequest::Trace
11:09:40.051 | ProviderAllocateGlobalCallHandleRequest::Trace :dwSequenceNumber = 0x0000000F
11:09:40.051 | ProviderAllocateGlobalCallHandleRequest::Trace
dummyHeader.dwLen =28
dummyHeader.dwType =0
dwMagicCookie =0xFFFFDDDD
dwProtocolVersion =0x000D0001
dwPDUNumber =11
dwHeaderSize =32
dwFixedSize =4
dwVariableSize =0
11:09:40.051 |<--ProviderAllocateGlobalCallHandleRequest::Trace
11:09:40.051 | SendMessage() sent message number 0x0000000b, sequence number 0x0000000f, 36 bytes
11:09:40.051 |<--SendMessage()
11:09:40.051 |<--CCtiInterface::sendCtiMessage()
11:09:40.051 |-->CSynchResponseObject::wait()
11:09:40.051 | CSynchResponseObject::wait() Waiting to receive synchronous response or timeout 15000
11:09:40.065 | CSelsiusTSPLink::getMessage() QBE message header: {{0x00000028, 0x00000000}, 0xFFFFDDDD, 0x000D0001, 0x0000000C, 0x00000020, 0x00000010, 0x00000000}
11:09:40.065 | CSelsiusTSPLink::getMessage() Read 48 bytes, message number is 0x0000000c
11:09:40.065 |<--CSelsiusTSPLink::getMessage()
11:09:40.065 | CCtiReceiver::receiveLoop() Received message. PDU# 0x0000000C(12)
11:09:40.065 |-->ProviderAllocateGlobalCallHandleResponse::qbeTrace
11:09:40.065 | ProviderAllocateGlobalCallHandleResponse::qbeTrace seq# =0x0000000F result =0x00000000
11:09:40.065 | ProviderAllocateGlobalCallHandleResponse::qbeTrace {{0x00000028, 0x00000000}, 0xFFFFDDDD, 0x000D0001, 0x0000000C, 0x00000020, 0x00000010, 0x00000000}
11:09:40.065 | ProviderAllocateGlobalCallHandleResponse::qbeTrace
globalCallHandle.callManagerId =3
globalCallHandle.callLegId =0x00002065
11:09:40.065 |<--ProviderAllocateGlobalCallHandleResponse::qbeTrace
11:09:40.065 |-->CCtiInterface:
rocessResponse() 11:09:40.065 | CCtiInterface:
rocessResponse() Found mapping seq#: 0x0000000F to responseObject: 0x0142DC6811:09:40.065 |-->CSynchResponseObject::notify()
11:09:40.065 |<--CSynchResponseObject::notify()
11:09:40.065 |<--CCtiInterface:
rocessResponse() 11:09:40.065 | CCtiReceiver::receiveLoop() Server heartbeat: 30. Waiting 60 seconds for a message (countdown: 60).
11:09:40.066 |-->CSelsiusTSPLink::getMessage()
11:09:40.066 |<--CSynchResponseObject::wait()
11:09:40.066 |<--CCtiInterface::sendSynchronousCtiRequest(): tId=0x00000B80
11:09:40.066 |-->CCtiInterface:
rocessProviderAllocateGlobalCallHandleResponse() 11:09:40.066 | CCtiInterface:
rocessProviderAllocateGlobalCallHandleResponse() Result of Provider Allocate Global Call Handle request is 011:09:40.066 |<--CCtiInterface:
rocessProviderAllocateGlobalCallHandleResponse() 11:09:40.066 |<--CCtiInterface::SendAllocateGlobalCallHandleRequest()
11:09:40.066 | CSelsiusTSPLine::MakeCall() line id=0x00001A36 Allocated a global call handle for initiating a call: call manager id=0x3, global call id=0x2065
11:09:40.066 |-->CSelsiusTSPCallList::GetNewCall()
11:09:40.066 |-->CTspCallInfo::CTspCallInfo()
11:09:40.066 |<--CTspCallInfo::CTspCallInfo()
11:09:40.066 |-->CSelsiusTSPCall::CSelsiusTSPCall()
11:09:40.066 | CSelsiusTSPCall::CSelsiusTSPCall() setting SecureMemMgr = 0x015016F8
11:09:40.066 | CSelsiusTSPCall::CSelsiusTSPCall() setting BlockDynamicDataflag [0]
11:09:40.066 | CSelsiusTSPCall::CSelsiusTSPCall() setting UseModifiedDNForExternalParty flag [0]
11:09:40.066 |<--CSelsiusTSPCall::CSelsiusTSPCall()
11:09:40.066 | CSelsiusTSPCallList::GetNewCall() callIndex=0x00000000 permLineId=0x80361A01 call=0x02507DB0 m_Call=0x02507DB0 m_LastNewCallIndex=0x00000000
11:09:40.066 |<--CSelsiusTSPCallList::GetNewCall()
11:09:40.066 |-->CScopedCriticalSection::CScopedCriticalSection() [0x01435158]
11:09:40.066 |<--CScopedCriticalSection::CScopedCriticalSection() [0x01435158]
11:09:40.066 |-->CCtiInterface::CtiLineCallInitiate()
11:09:40.066 |-->CQBE_Builder::qbePut:QBE_ByteArray()
11:09:40.066 | CQBE_Builder::qbePut:QBE_ByteArray() else case (either pArray or ArraySize are NULL)
11:09:40.066 |<--CQBE_Builder::qbePut:QBE_ByteArray()
11:09:40.066 |-->CCtiInterface::sendAsynchronousCtiLineRequest(): appRequestId=0x00010399
11:09:40.066 |-->CCtiInterface::sendAsyncCtiRequest(): ctiRequestId=16 tId=0x00000B80
11:09:40.066 |-->CCtiRequestMap::add()
11:09:40.066 | CCtiRequestMap::add() Adding map entry for sequenceNumber(0x00000010) to responseObject(0x014FF000)
11:09:40.066 |<--CCtiRequestMap::add()
11:09:40.066 |-->CCtiInterface::sendCtiMessage()
11:09:40.066 |-->SendMessage()
11:09:40.066 |-->LineCallInitiateRequest::Trace
11:09:40.066 | LineCallInitiateRequest::Trace :dwSequenceNumber = 0x00000010
11:09:40.066 | LineCallInitiateRequest::Trace
dummyHeader.dwLen =101
dummyHeader.dwType =0
dwMagicCookie =0xFFFFDDDD
dwProtocolVersion =0x000D0001
dwPDUNumber =43
dwHeaderSize =32
dwFixedSize =60
dwVariableSize =17
11:09:40.066 | LineCallInitiateRequest::Trace
CtiLineHandle.callManagerId =6
CtiLineHandle.lineId =0x00001A36
11:09:40.066 | LineCallInitiateRequest::Trace
globalCallHandle.callManagerId =3
globalCallHandle.callLegId =0x00002065
11:09:40.066 | LineCallInitiateRequest::Trace
dwCallingAddressOffset =0x0000005C
dwCallingAddressSize =5
CallingAddress =9137
dwDestAddressOffset =0x00000061
dwDestAddressSize =12
DestAddress =10211478583
dwMediaDeviceNameOffset =0x00000000
dwMediaDeviceNameSize =0
MediaDeviceName =
dwMediaResourceId =0
11:09:40.066 | LineCallInitiateRequest::Trace
UserData:size = 0
11:09:40.066 |<--LineCallInitiateRequest::Trace
11:09:40.066 | SendMessage() sent message number 0x0000002b, sequence number 0x00000010, 109 bytes
11:09:40.066 |<--SendMessage()
11:09:40.066 |<--CCtiInterface::sendCtiMessage()
11:09:40.066 |<--CCtiInterface::sendAsyncCtiRequest(): ctiRequestId=16 tId=0x00000B80
11:09:40.066 |<--CCtiInterface::sendAsynchronousCtiLineRequest(): appRequestId=0x00010399
11:09:40.066 |<--CCtiInterface::CtiLineCallInitiate()
11:09:40.066 |-->CSelsiusTSPLine::AddRequestID() [0x00001A36]
11:09:40.066 |<--CSelsiusTSPLine::AddRequestID() [0x00001A36]
11:09:40.066 |-->CSelsiusTSPCall::SetNoAnswerTimeout() 0x00000000
11:09:40.066 |<--CSelsiusTSPCall::SetNoAnswerTimeout() 0x00000000
11:09:40.066 |-->CScopedCriticalSection::~CScopedCriticalSection() [0x01435158]
11:09:40.066 |<--CScopedCriticalSection::~CScopedCriticalSection() [0x01435158]
11:09:40.066 |<--CSelsiusTSPLine::MakeCall() line id=0x00001A36
11:09:40.066 |<--SelsiusTSP::TSPI_lineMakeCall(0x01434E58)
11:09:40.066 | TSPI_lineMakeCall() TSPI_lineMakeCall returns = 0x00010399
11:09:40.066 |<--TSPI_lineMakeCall()
11:09:41.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:41.066 |<--CSelsiusTSPLink::getMessage()
11:09:41.066 |-->CSelsiusTSPLink::getMessage()
11:09:42.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:42.066 |<--CSelsiusTSPLink::getMessage()
11:09:42.066 |-->CSelsiusTSPLink::getMessage()
11:09:43.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:43.066 |<--CSelsiusTSPLink::getMessage()
11:09:43.066 |-->CSelsiusTSPLink::getMessage()
11:09:44.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:44.066 |<--CSelsiusTSPLink::getMessage()
11:09:44.066 |-->CSelsiusTSPLink::getMessage()
11:09:45.066 | CSelsiusTSPLink::getMessage() Link read time out. hSocket=1304
11:09:45.066 |<--CSelsiusTSPLink::getMessage()
11:09:45.066 |-->CSelsiusTSPLink::getMessage()
11:09:45.066 | CSelsiusTSPLink::getMessage() QBE message header: {{0x00000046, 0x00000000}, 0xFFFFDDDD, 0x000D0001, 0x00000000, 0x00000020, 0x00000010, 0x0000001E}
11:09:45.066 | CSelsiusTSPLink::getMessage() Read 78 bytes, message number is 0x00000000
11:09:45.066 |<--CSelsiusTSPLink::getMessage()
11:09:45.066 | CCtiReceiver::receiveLoop() Received message. PDU# 0x00000000(0)
11:09:45.066 |-->FailureResponse::qbeTrace
11:09:45.066 | FailureResponse::qbeTrace seq# =0x0000000E result =0x8CCC0001
11:09:45.066 | FailureResponse::qbeTrace {{0x00000046, 0x00000000}, 0xFFFFDDDD, 0x000D0001, 0x00000000, 0x00000020, 0x00000010, 0x0000001E}
11:09:45.066 | FailureResponse::qbeTrace
dwResult =0x8CCC0001
Description : {0x00000030, 30, Line get info request failure }
At times the tsp doesn't update with changes and only after kiling the tapi srvc will updates start showing again.