Calls drop after pickup with ActivaTSP

Help
2011-04-26
2013-05-30
  • James Walsh

    James Walsh - 2011-04-26

    I have installed ActivaTSP v1.6.4
    I am using Asterisk 1.8.3.2    (specifically PBXinaFlash 1.7.5.5)

    I am trying to get the TAPI dialer in Outlook 2010 to work.  So far, when I make a call, the local extension rings and I am able to answer whereupon I usually hear a ringing tone.  However, as soon as the call is answered, the line hangs up.  I have tested this by calling my own cellphone and can confirm that this is not because the recipient hangs up.

    Line DN:   704
    Line Prefix:   AST
    Caller ID Name:          <blank>
    Context 
        Outgoing:   from-internal
        Agent:         from-internal
    Asterisk Connection
        Host IP:   10.10.2.150
        Port:          5038
        User:        <special Asterisk Admin acct created for TAPI>
        Password:   <associated password>
    

    My log looks as follows:

    04/26/11 14:50:08 [3372] TRACE [TAPIProvider] TSPI_lineGetDevCaps() dwDeviceIdBase=0x7 dwDeviceID=0x7
    04/26/11 14:53:50 [3600] TRACE [TAPIProvider] TSPI_lineOpen() dwDeviceID=0x7 htLine=0x6445fc0
    04/26/11 14:53:50 [3600] INFO  [ASTProvider] Connect(10.10.2.150,5038,actCRM,act1ngUP)
    04/26/11 14:53:50 [3600] TRACE [ASTProvider] ASTProvider::SendCommand => 
    Action: Login
    UserName: *snip*
    Secret: *snip*
    ActionID: 23
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::ReaderProc
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] Asterisk protocol header: Asterisk Call Manager/1.1
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol response__________________________
    04/26/11 14:53:50 [3600] TRACE [ASTProvider] Connect() returns ok
    04/26/11 14:53:50 [3600] TRACE [ASTCstaProvider] ASTCstaProvider::OpenMonitor device = 704 => 704
    04/26/11 14:53:50 [3600] TRACE [ASTCallMap]   first monitor for this device: {704,7}
    04/26/11 14:53:50 [3600] TRACE [TAPIProvider] AddTapiLine xref=7 htapiLine=0x6445fc0 pTapiLine=0x6845e38
    04/26/11 14:53:50 [3600] TRACE [TSP] TSPI_lineGetNumAddressIDs hdLine=00000007
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider] TSPI_lineMakeCall() hdLine=0x7, htCall=0x54a0540, phdCall=0x54a0558, calledDevice=T 16463850500
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider]   filtered calledDevice T 16463850500 => 16463850500
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider]  Reading NOANSWERTIMEOUT 0
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider]  UserData not found
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider]  creating TapiCall 0x68485d0 with htCall 0x54a0540
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider] ASTTapiProvider::AddTapiCall pNewTapiCall=0x68485d0 callId=37, htapicall=0x54a0540, callerId=704, calledId=16463850500 userData=
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider]   first TapiCall for this callid: [37] => 0x68485d0
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider]  Executing MakeCall
    04/26/11 14:53:50 [3372] TRACE [ASTCallMap] AddConnectionToCallModel {37, 704} => INITIALIZED
    04/26/11 14:53:50 [3372] TRACE [ASTCallMap]  done, now CALL map has 1 items
    04/26/11 14:53:50 [3372] TRACE [ASTProvider] ASTProvider::Originate call 37 channel:Local/704@from-internal callerId:704 to calledExtension:16463850500 in context:from-internal, callerIdName=       timeout=30
    04/26/11 14:53:50 [3372] TRACE [ASTProvider] ASTProvider::SendCommand => 
    Action: Originate
    Channel: Local/704@from-internal/n
    Exten: 16463850500
    Priority: 1
    Callerid:       #CallId=37 <704>
    Context: from-internal
    Variable: originating=704
    ActionID: 24
    Timeout: 30000
    Async: 1
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol response__________________________
    04/26/11 14:53:50 [3372] TRACE [ASTProvider]   Originate success
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider]  makecall or makepredictivecall success
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider]   NEW callId=37 for htapicall=0x54a0540 and hdcall=0x54a0558
    04/26/11 14:53:50 [3372] TRACE [TAPIProvider]   returning dwRequestId 65716
    04/26/11 14:53:50 [2800] TRACE [TAPIProvider] TSPI_lineGetCallInfo: changing callerIDName= by callerId=704 because is unknown
    04/26/11 14:53:50 [2800] TRACE [TAPIProvider] TSPI_lineGetCallInfo hdCall=0x68485d0 callerId=704, callerIdName=704, calledId=16463850500, calledIdName=16463850500, connectedId=, connectedIdName=, redirectingId=, redirectingIdName=, redirectionId=, userData=, isPredictive=0, dwOrigin=0x10
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1303844028.34"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Down"; ev.m_channel="Local/704@from-internal-5cef;1"; m_pxCstaProvider->OnNewChannelEvent(ev);
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1303844028.34 and callid =38
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   setting {1303844028.34}.callerID=, callerIdName=
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   setting {1303844028.34}.channel=Local/704@from-internal-5cef;1, address=704
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   state = DOWN => do nothing
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1303844028.35"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Ring"; ev.m_channel="Local/704@from-internal-5cef;2"; m_pxCstaProvider->OnNewChannelEvent(ev);
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1303844028.35 and callid =39
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   setting {1303844028.35}.callerID=, callerIdName=
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   setting {1303844028.35}.channel=Local/704@from-internal-5cef;2, address=704
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]  link call {1303844028.35} with call {1303844028.34}
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   state = RING => Send ORIGINATED to {1303844028.35}.address=704
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionOriginated uniqueId=1303844028.35, address=704
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1303844028.34"; ev.m_callerId="704"; ev.m_callerIdName="#CallId=37"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   overriding {1303844028.34}. to new callerId 704
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call containsCallId(37)
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   overriding {1303844028.34}.38 to new callId 37
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1303844028.34"; ev.m_callerId="704"; ev.m_callerIdName="#CallId=37"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call containsCallId(37)
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   overriding {1303844028.34}.37 to new callId 37
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1303844028.36"; ev.m_callerId="704"; ev.m_callerIdName="device"; ev.m_state="Down"; ev.m_channel="SIP/704-00000006"; m_pxCstaProvider->OnNewChannelEvent(ev);
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1303844028.36 and callid =40
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call does not containsCallId
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   setting {1303844028.36}.callerID=704, callerIdName=device
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   setting {1303844028.36}.channel=SIP/704-00000006, address=704
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   state = DOWN => do nothing
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] OnDialEvent:CFT: ev.m_srcUniqueId="1303844028.35"; ev.m_destUniqueId="1303844028.36"; ev.m_callerIdName="#CallId=37"; ev.m_callerId="704"; m_pxCstaProvider->OnDialEvent(ev);
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   linked calls {1303844028.35} <- {1303844028.36}
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call containsCallId(37)
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   overriding {1303844028.35}.39 to new callId 37
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   overriding {1303844028.36}.40 to new callId 37
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] overriding {1303844028.35}. to new callerid 704
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1303844028.36"; ev.m_callerId="704"; ev.m_callerIdName=""; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844028.34"; ev.m_callerIdName="Kitchen"; ev.m_state="Ringing"; ev.m_channel="Local/704@from-internal-5cef;1"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call does not containsCallId
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   setting {1303844028.34}.callerID=704, callerIdName=Kitchen
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1303844028.34}.address=704
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1303844028.34, address=704
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x68497b8)
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:50 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844028.36"; ev.m_callerIdName=""; ev.m_state="Ringing"; ev.m_channel="SIP/704-00000006"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1303844028.36}.address=704
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1303844028.36, address=704
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x684f210)
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap] GetCIDInfoFromSourceCall(1303844028.36)
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap]   Exiting with cid/cidname/userData=704/Kitchen/
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap] AddConnectionToCallModel {37, 704} => ALERTING
    04/26/11 14:53:50 [5756] TRACE [ASTCallMap]  done, now CALL map has 1 items
    04/26/11 14:53:50 [5756] TRACE [ASTCstaProvider]   event minimization RULE-4: (callerid = 704) == (called = 704) == (address = 704)
    04/26/11 14:53:50 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844028.36"; ev.m_callerIdName=""; ev.m_state="Up"; ev.m_channel="SIP/704-00000006"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1303844028.36}.address=704
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1303844028.36, address=704
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x684f210)
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap] GetCIDInfoFromSourceCall(1303844028.36)
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap]   Exiting with cid/cidname/userData=704/Kitchen/
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap] AddConnectionToCallModel {37, 704} => CONNECTED
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap]  done, now CALL map has 1 items
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   event minimization RULE-4: (callerid = 704) == (called = 704) == (address = 704)
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844028.35"; ev.m_callerIdName="#CallId=37"; ev.m_state="Up"; ev.m_channel="Local/704@from-internal-5cef;2"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call containsCallId(37)
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   setting {1303844028.35}.callerID=704, callerIdName=
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1303844028.35}.address=704
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1303844028.35, address=704
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x68496a0)
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844028.34"; ev.m_callerIdName="Kitchen"; ev.m_state="Up"; ev.m_channel="Local/704@from-internal-5cef;1"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call does not containsCallId
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   setting {1303844028.34}.callerID=704, callerIdName=Kitchen
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1303844028.34}.address=704
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1303844028.34, address=704
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x68497b8)
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => originateresponse
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => bridge
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] OnLinkEvent:CFT: ev.m_srcUniqueId="1303844028.35"; ev.m_destUniqueId="1303844028.36"; m_pxCstaProvider->OnLinkEvent(ev);
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   set {1303844028.36}.lastRedirectionDevice=
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1303844032.37"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Down"; ev.m_channel="Local/16463850500@gvoice-9a41;1"; m_pxCstaProvider->OnNewChannelEvent(ev);
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1303844032.37 and callid =41
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   setting {1303844032.37}.callerID=, callerIdName=
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   setting {1303844032.37}.channel=Local/16463850500@gvoice-9a41;1, address=16463850500
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   state = DOWN => do nothing
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1303844032.38"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Ring"; ev.m_channel="Local/16463850500@gvoice-9a41;2"; m_pxCstaProvider->OnNewChannelEvent(ev);
    04/26/11 14:53:53 [5756] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1303844032.38 and callid =42
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   setting {1303844032.38}.callerID=, callerIdName=
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   setting {1303844032.38}.channel=Local/16463850500@gvoice-9a41;2, address=16463850500
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]  link call {1303844032.38} with call {1303844032.37}
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   state = RING => Send ORIGINATED to {1303844032.38}.address=16463850500
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionOriginated uniqueId=1303844032.38, address=16463850500
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1303844032.37"; ev.m_callerId="704"; ev.m_callerIdName="#CallId=37"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   overriding {1303844032.37}. to new callerId 704
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call containsCallId(37)
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   overriding {1303844032.37}.41 to new callId 37
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] OnDialEvent:CFT: ev.m_srcUniqueId="1303844028.34"; ev.m_destUniqueId="1303844032.37"; ev.m_callerIdName="<unknown>"; ev.m_callerId="12128732982"; m_pxCstaProvider->OnDialEvent(ev);
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   linked calls {1303844028.34} <- {1303844032.37}
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Dial event don't contain callid, we try to get it using GetLogicCallId
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] Call logicCallId(): 37
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   overriding {1303844028.34}.37 to new callId 37
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider]   overriding {1303844032.37}.37 to new callId 37
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] overriding {1303844028.34}. to new callerid 12128732982
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:53 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
    04/26/11 14:53:53 [5756] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1303844032.37"; ev.m_callerId="16463850500"; ev.m_callerIdName=""; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    04/26/11 14:53:53 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:54 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1303844033.39"; ev.m_callerId=""; ev.m_callerIdName="+16463850500@voice.google.com"; ev.m_state="Down"; ev.m_channel="Gtalk/+16463850500@voice.google.com-7e6c"; m_pxCstaProvider->OnNewChannelEvent(ev);
    04/26/11 14:53:54 [5756] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1303844033.39 and callid =43
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] Call does not containsCallId
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   setting {1303844033.39}.callerID=, callerIdName=+16463850500@voice.google.com
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   setting {1303844033.39}.channel=Gtalk/+16463850500@voice.google.com-7e6c, address=+16463850500@voice.google.com
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   state = DOWN => do nothing
    04/26/11 14:53:54 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:54 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844033.39"; ev.m_callerIdName="+16463850500@voice.google.com"; ev.m_state="Ring"; ev.m_channel="Gtalk/+16463850500@voice.google.com-7e6c"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] Call does not containsCallId
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   setting {1303844033.39}.callerID=, callerIdName=+16463850500@voice.google.com
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   state = RING => Send ORIGINATED to {1303844033.39}.address=+16463850500@voice.google.com
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionOriginated uniqueId=1303844033.39, address=+16463850500@voice.google.com
    04/26/11 14:53:54 [5756] TRACE [ASTCallMap] AddConnectionToCallModel {43, +16463850500@voice.google.com} => INITIALIZED
    04/26/11 14:53:54 [5756] TRACE [ASTCallMap]  done, now CALL map has 2 items
    04/26/11 14:53:54 [5756] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 43
    04/26/11 14:53:54 [5756] TRACE [ASTCallMap]   num_monitors = 0
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   do not send EVENTS because not exist any monitors in call 43
    04/26/11 14:53:54 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:54 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] OnDialEvent:CFT: ev.m_srcUniqueId="1303844032.38"; ev.m_destUniqueId="1303844033.39"; ev.m_callerIdName="<unknown>"; ev.m_callerId="12128732982"; m_pxCstaProvider->OnDialEvent(ev);
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   linked calls {1303844032.38} <- {1303844033.39}
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] Dial event don't contain callid, we try to get it using GetLogicCallId
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] Call logicCallId(): 37
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   overriding {1303844032.38}.42 to new callId 37
    04/26/11 14:53:54 [5756] TRACE [ASTCallMap] RemoveCall {42}
    04/26/11 14:53:54 [5756] TRACE [ASTCallMap]     {42} NOT IN CALL-MONITOR MAP
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   overriding {1303844033.39}.43 to new callId 37
    04/26/11 14:53:54 [5756] TRACE [ASTCallMap] RemoveCall {43}
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] overriding {1303844032.38}. to new callerid 12128732982
    04/26/11 14:53:54 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:53:54 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1303844033.39"; ev.m_callerId="16463850500"; ev.m_callerIdName=""; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    04/26/11 14:53:54 [5756] TRACE [ASTCstaProvider]   overriding {1303844033.39}. to new callerId 16463850500
    04/26/11 14:53:54 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:04 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844032.37"; ev.m_callerIdName=""; ev.m_state="Ringing"; ev.m_channel="Local/16463850500@gvoice-9a41;1"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1303844032.37}.address=16463850500
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1303844032.37, address=16463850500
    04/26/11 14:54:04 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x6848c30)
    04/26/11 14:54:04 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
    04/26/11 14:54:04 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:04 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844028.35"; ev.m_callerIdName="#CallId=37"; ev.m_state="Ringing"; ev.m_channel="Local/704@from-internal-5cef;2"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider] Call does not contains UserData
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider] Call containsCallId(37)
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider]   overriding {1303844028.35}.37 to new callId 37
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider] Call is NOT predictive
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider]   setting {1303844028.35}.callerID=704, callerIdName=
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1303844028.35}.address=704
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1303844028.35, address=704
    04/26/11 14:54:04 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x68496a0)
    04/26/11 14:54:04 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
    04/26/11 14:54:04 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:04 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => unlink
    04/26/11 14:54:04 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:04 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => bridge
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider] OnLinkEvent:CFT: ev.m_srcUniqueId="1303844028.35"; ev.m_destUniqueId="1303844028.36"; m_pxCstaProvider->OnLinkEvent(ev);
    04/26/11 14:54:04 [5756] TRACE [ASTCstaProvider]   set {1303844028.36}.lastRedirectionDevice=
    04/26/11 14:54:04 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    
     
  • James Walsh

    James Walsh - 2011-04-26

    By contrast, when dialing from the extenstion manually, this is what the call log shows

     
  • James Walsh

    James Walsh - 2011-04-26

    Oops, hit enter too quickly.

    Direct dialing from the extension shows:

    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844033.39"; ev.m_callerIdName=""; ev.m_state="Up"; ev.m_channel="Gtalk/+16463850500@voice.google.com-7e6c"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1303844033.39}.address=+16463850500@voice.google.com
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1303844033.39, address=+16463850500@voice.google.com
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x684feb0)
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetCIDInfoFromSourceCall(1303844033.39)
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   Exiting with cid/cidname/userData=12128732982/<unknown>/
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] AddConnectionToCallModel {37, +16463850500@voice.google.com} => CONNECTED
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]  done, now CALL map has 1 items
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   source call is {1303844028.34} and lastRedirection=
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 37
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   num_monitors = 1
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]     sending event:CFTE:ESTABLISHED to xref=7, address=+16463850500@voice.google.com, callid=37, lastRedirection=, userData=
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider] OnEstablished xref=7 callId=37, establishedDevice=+16463850500@voice.google.com, callerId=12128732982, callerIdName=<unknown>, calledDevice =16463850500, lastRedirectingDevice=, userData= cause=0
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]  searching a TapiCall with callId 37 in tapiLine 0x6845e38
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]     htapiline=0x6445fc0, deviceID=704, htapicall=0x54a0540, callerid=12128732982, callerIdName=<unknown>, calleddevice=16463850500, lastRedirection=, userData=
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]   LINECALLSTATE_CONNECTED  htapicall=0x54a0540
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844032.38"; ev.m_callerIdName=""; ev.m_state="Up"; ev.m_channel="Local/16463850500@gvoice-9a41;2"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1303844032.38}.address=16463850500
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1303844032.38, address=16463850500
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x684f328)
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => bridge
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnLinkEvent:CFT: ev.m_srcUniqueId="1303844032.38"; ev.m_destUniqueId="1303844033.39"; m_pxCstaProvider->OnLinkEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   set {1303844033.39}.lastRedirectionDevice=
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1303844032.37"; ev.m_callerIdName=""; ev.m_state="Up"; ev.m_channel="Local/16463850500@gvoice-9a41;1"; m_pxCstaProvider->OnNewStateEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1303844032.37}.address=16463850500
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1303844032.37, address=16463850500
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0x6848c30)
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   SourceCall is 1303844028.34
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => bridge
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnLinkEvent:CFT: ev.m_srcUniqueId="1303844028.34"; ev.m_destUniqueId="1303844032.37"; m_pxCstaProvider->OnLinkEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   set {1303844032.37}.lastRedirectionDevice=
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => unlink
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => bridge
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnLinkEvent:CFT: ev.m_srcUniqueId="1303844028.34"; ev.m_destUniqueId="1303844032.37"; m_pxCstaProvider->OnLinkEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   set {1303844032.37}.lastRedirectionDevice=
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => unlink
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => bridge
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnLinkEvent:CFT: ev.m_srcUniqueId="1303844028.35"; ev.m_destUniqueId="1303844028.36"; m_pxCstaProvider->OnLinkEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   set {1303844028.36}.lastRedirectionDevice=
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => rename
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnRenameEvent:CFT: ev.m_uniqueId="1303844033.39"; ev.m_oldname="Gtalk/+16463850500@voice.google.com-7e6c"; ev.m_newname="Gtalk/+16463850500@voice.google.com-7e6c<MASQ>"; m_pxCstaProvider->OnRenameEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0x684feb0)
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1303844033.39, logicaddress=+16463850500@voice.google.com, cause=0
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   rename channel [Gtalk/+16463850500@voice.google.com-7e6c] = > [Gtalk/+16463850500@voice.google.com-7e6c<MASQ>]
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 37
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   num_monitors = 1
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]     sending event:CFTE:CONNCLEARED to xref=7, address=704, callid=37
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider] OnConnectionCleared xref=7 callId=37, releasingDevice=+16463850500@voice.google.com cause=0
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]  searching a TapiCall with callId 37 in tapiLine 0x6845e38
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]     htapiline=0x6445fc0, deviceID=704, htapicall=0x54a0540, releasingDevice=+16463850500@voice.google.com, callerid=N/A, callerIdName=N/A, calleddevice=N/A, lastRedirection=N/A
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]   LINEDISCONNECTMODE_NORMAL htapicall=0x54a0540
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [3372] TRACE [TAPIProvider] TSPI_lineDrop() hdCall=0x68485d0
    04/26/11 14:54:24 [3372] TRACE [TAPIProvider]   got TapiCall=0x68485d0
    04/26/11 14:54:24 [3372] TRACE [TAPIProvider]   got callID=37
    04/26/11 14:54:24 [3372] TRACE [ASTCstaProvider] ASTCstaProvider::ClearConnection callID=37 address=704
    04/26/11 14:54:24 [3372] TRACE [ASTCstaProvider]   Hangup callid=37,channel=Local/704@from-internal-5cef;1
    04/26/11 14:54:24 [3372] TRACE [ASTProvider] ASTProvider::Hangup channel=Local/704@from-internal-5cef;1
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => rename
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnRenameEvent:CFT: ev.m_uniqueId="1303844032.37"; ev.m_oldname="Local/16463850500@gvoice-9a41;1"; ev.m_newname="Gtalk/+16463850500@voice.google.com-7e6c"; m_pxCstaProvider->OnRenameEvent(ev);
    04/26/11 14:54:24 [3372] TRACE [ASTProvider] ASTProvider::SendCommand => 
    Action: Hangup
    Channel: Local/704@from-internal-5cef;1
    ActionID: 25
    Async: 1
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   rename channel [Local/16463850500@gvoice-9a41;1] = > [Gtalk/+16463850500@voice.google.com-7e6c]
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => rename
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnRenameEvent:CFT: ev.m_uniqueId="1303844033.39"; ev.m_oldname="Gtalk/+16463850500@voice.google.com-7e6c<MASQ>"; ev.m_newname="Local/16463850500@gvoice-9a41;1<ZOMBIE>"; m_pxCstaProvider->OnRenameEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0x684feb0)
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1303844033.39, logicaddress=+16463850500@voice.google.com, cause=0
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   rename channel [Gtalk/+16463850500@voice.google.com-7e6c<MASQ>] = > [Local/16463850500@gvoice-9a41;1<ZOMBIE>]
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 37
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   num_monitors = 1
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]     sending event:CFTE:CONNCLEARED to xref=7, address=704, callid=37
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider] OnConnectionCleared xref=7 callId=37, releasingDevice=+16463850500@voice.google.com cause=0
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]  searching a TapiCall with callId 37 in tapiLine 0x6845e38
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]     htapiline=0x6445fc0, deviceID=704, htapicall=0x54a0540, releasingDevice=+16463850500@voice.google.com, callerid=N/A, callerIdName=N/A, calleddevice=N/A, lastRedirection=N/A
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]   LINEDISCONNECTMODE_NORMAL htapicall=0x54a0540
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1303844032.37"; ev.m_callerId="16463850500"; ev.m_callerIdName=""; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => unlink
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1303844033.39"; ev.m_cause="16"; m_pxCstaProvider->OnHangupEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetStateOfDevice {37, 16463850500}
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]  not found device 16463850500 with callId 37
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]  callMap.size == 6
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   handleConnectionDisconnected {1303844033.39} to 16463850500
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0x684feb0)
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1303844033.39, logicaddress=16463850500, cause=0
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   event minimization RULE-10: Do not send DISCONNECTED to local channels. But send it if call has no destination.
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   removed uniqueId=1303844033.39 call from MAP
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1303844032.38"; ev.m_cause="16"; m_pxCstaProvider->OnHangupEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetStateOfDevice {37, +16463850500@voice.google.com}
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]    deviceState = CONNECTED
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]  callMap.size == 5
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   handleConnectionDisconnected {1303844032.38} to 16463850500
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0x684f328)
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1303844032.38, logicaddress=16463850500, cause=0
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   event minimization RULE-10: Do not send DISCONNECTED to local channels. But send it if call has no destination.
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   removed uniqueId=1303844032.38 call from MAP
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol response__________________________
    04/26/11 14:54:24 [3372] TRACE [ASTProvider]   return = ok
    04/26/11 14:54:24 [3372] TRACE [TAPIProvider]   ClearConnection() returned ok. Sending LINECALLSTATE_IDLE  htapicall=0x54a0540
    04/26/11 14:54:24 [604] TRACE [TAPIProvider] TSPI_lineDrop() hdCall=0x68485d0
    04/26/11 14:54:24 [604] TRACE [TAPIProvider]   got TapiCall=0x68485d0
    04/26/11 14:54:24 [604] TRACE [TAPIProvider]   got callID=37
    04/26/11 14:54:24 [604] TRACE [ASTCstaProvider] ASTCstaProvider::ClearConnection callID=37 address=704
    04/26/11 14:54:24 [604] TRACE [ASTCstaProvider]   Hangup callid=37,channel=Local/704@from-internal-5cef;1
    04/26/11 14:54:24 [604] TRACE [ASTProvider] ASTProvider::Hangup channel=Local/704@from-internal-5cef;1
    04/26/11 14:54:24 [604] TRACE [ASTProvider] ASTProvider::SendCommand => 
    Action: Hangup
    Channel: Local/704@from-internal-5cef;1
    ActionID: 26
    Async: 1
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => unlink
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1303844032.37"; ev.m_cause="16"; m_pxCstaProvider->OnHangupEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetStateOfDevice {37, 704}
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]    deviceState = CONNECTED
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]  callMap.size == 4
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   handleConnectionDisconnected {1303844032.37} to +16463850500@voice.google.com
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0x6848c30)
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1303844032.37, logicaddress=+16463850500@voice.google.com, cause=0
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 37
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   num_monitors = 1
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]     sending event:CFTE:CONNCLEARED to xref=7, address=704, callid=37
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider] OnConnectionCleared xref=7 callId=37, releasingDevice=+16463850500@voice.google.com cause=0
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]  searching a TapiCall with callId 37 in tapiLine 0x6845e38
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider] don't send events because call is idle
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] RemoveConnection {37}=> +16463850500@voice.google.com
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   removed uniqueId=1303844032.37 call from MAP
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1303844028.34"; ev.m_cause="16"; m_pxCstaProvider->OnHangupEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetStateOfDevice {37, 704}
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]    deviceState = CONNECTED
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   handleConnectionDisconnected {1303844028.34} to 704
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0x68497b8)
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1303844028.34, logicaddress=704, cause=0
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   event minimization RULE-10: Do not send DISCONNECTED to local channels. But send it if call has no destination.
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   transferring callid and other parameters to its destination asteriskCall in the 'call walk path' currently destination call {1303844028.35}.callid = 37
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]     now destination call {1303844028.35}.callid = 37 and sourceUniqueId=''
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   removed uniqueId=1303844028.34 call from MAP
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => unlink
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1303844028.36"; ev.m_cause="16"; m_pxCstaProvider->OnHangupEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetStateOfDevice {37, 704}
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]    deviceState = CONNECTED
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]  callMap.size == 2
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   handleConnectionDisconnected {1303844028.36} to 704
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0x684f210)
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1303844028.36, logicaddress=704, cause=0
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 37
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   num_monitors = 1
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]     sending event:CFTE:CONNCLEARED to xref=7, address=704, callid=37
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider] OnConnectionCleared xref=7 callId=37, releasingDevice=704 cause=0
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider]  searching a TapiCall with callId 37 in tapiLine 0x6845e38
    04/26/11 14:54:24 [5756] TRACE [TAPIProvider] don't send events because call is idle
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] RemoveConnection {37}=> 704
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   removed uniqueId=1303844028.36 call from MAP
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1303844028.35"; ev.m_cause="16"; m_pxCstaProvider->OnHangupEvent(ev);
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetStateOfDevice {37, 704}
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]  call 37 not found
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   handleConnectionDisconnected {1303844028.35} to 704
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0x68496a0)
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1303844028.35, logicaddress=704, cause=0
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   event minimization RULE-10: Do not send DISCONNECTED to local channels. But send it if call has no destination.
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   removed uniqueId=1303844028.35 call from MAP
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   handleCallDisconnected {37} was the last one
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 37
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]   callerId not found
    04/26/11 14:54:24 [5756] WARN  [ASTCstaProvider]   do not send EVENTS because not exist any monitors in call 37
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap] RemoveCall {37}
    04/26/11 14:54:24 [5756] TRACE [ASTCallMap]     {37} NOT IN CALL-MONITOR MAP
    04/26/11 14:54:24 [5756] TRACE [ASTCstaProvider]   removed entry with callId=37 from MAP
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
    04/26/11 14:54:24 [5756] TRACE [ASTProvider]  <== asterisk protocol response__________________________
    04/26/11 14:54:24 [604] ERROR [ASTProvider]   return = no such channel
    04/26/11 14:54:24 [604] TRACE [TAPIProvider]  ClearConnection() returned no such channel for this tapihandler and it is already idled!
    04/26/11 14:54:24 [3600] TRACE [TAPIProvider] TSPI_lineCloseCall() hdCall=0x68485d0
    04/26/11 14:54:24 [3600] TRACE [TAPIProvider] ASTTapiProvider::RemoveTapiCall hdrivercall=0x68485d0
    04/26/11 14:54:24 [3600] TRACE [TAPIProvider]   call had callid=37
    04/26/11 14:54:24 [3600] TRACE [TAPIProvider]     ...with 1 associated hdrvrcalls
    04/26/11 14:54:24 [3600] TRACE [TAPIProvider]   delete htcall 0x54a0540 and hdrvCall 0x68485d0
    04/26/11 14:54:24 [3600] TRACE [TAPIProvider]   deleted the last htapicall and the set of callid 37
    04/26/11 14:54:24 [3600] TRACE [TAPIProvider]   deleting pTapiCall addrs=704 htapiCall=0x54a0540
    04/26/11 14:54:24 [604] TRACE [TAPIProvider] TSPI_lineClose() hdLine=0x7
    04/26/11 14:54:24 [604] TRACE [TAPIProvider] RemoveTapiLine hdrvLine=0x7
    04/26/11 14:54:24 [604] TRACE [TAPIProvider]   was 704
    04/26/11 14:54:24 [604] TRACE [ASTCstaProvider] ASTCstaProvider::CloseMonitor xref = 7
    04/26/11 14:54:24 [604] TRACE [ASTCallMap]   erase xref map entry
    04/26/11 14:54:24 [604] TRACE [ASTCallMap]     erase extension map entry
    04/26/11 14:54:24 [604] TRACE [ASTCstaProvider]   return 1!
    04/26/11 14:54:24 [604] INFO  [TAPIProvider] Disconnect socked and clear callmaps because no line is open.
    04/26/11 14:54:24 [5756] INFO  [ASTProvider] Socket recv code = -1
    04/26/11 14:54:24 [5756] INFO  [ASTProvider] Error code 10053, The virtual circuit was terminated due to a time-out or other failure. The application should close the socket as it is no longer usable.
    04/26/11 14:54:24 [604] INFO  [ASTProvider] Socket closed without errors.
    04/26/11 14:54:24 [5756] TRACE [ASTProvider] ASTProvider::ReaderProc EXITS
    04/26/11 14:54:24 [604] TRACE [ASTProvider] WaitReaderThread => Thread terminated nicely
    04/26/11 14:54:24 [604] TRACE [TAPIProvider]  CallMapCleanup() cleaning maps
    

    Any suggestions as to why it is hanging up?

     
  • James Walsh

    James Walsh - 2011-04-28

    Anyone have any pointers?

     
  • andrea

    andrea - 2011-05-11

    The same problem here:
    Freepbx distro 2.9 (asterisk 1.8) , Windows 7 x64, Office 2010 32bit

     
  • activatsp

    activatsp - 2011-05-12

    Hi all,

    I tryed to analyze the logs, but in post 1 the log is incomplete, please reproduce the issue and paste the logs to the hangup events.

    Activa Team.

     
  • activatsp

    activatsp - 2011-05-24

    Hi!

    It seems that rename event isn'handled propertly, and it fire's a Connection Cleared…

    05/11/11 17:50:02 [5208] TRACE [ASTProvider] ASTProvider::HandleEvent => rename
    05/11/11 17:50:02 [5208] TRACE [ASTCstaProvider] OnRenameEvent:CFT: ev.m_uniqueId="1305129015.763"; ev.m_oldname="mISDN/tmp0-u195"; ev.m_newname="mISDN/1-u196"; m_pxCstaProvider->OnRenameEvent(ev);
    05/11/11 17:50:02 [5208] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0x290aa90)
    05/11/11 17:50:02 [5208] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1305129015.763, logicaddress=misdn/tmp0-u195, cause=0
    05/11/11 17:50:02 [5208] TRACE [ASTCstaProvider]   rename channel [mISDN/tmp0-u195] = > [mISDN/1-u196]
    05/11/11 17:50:02 [5208] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 2
    05/11/11 17:50:02 [5208] TRACE [ASTCallMap]   num_monitors = 1
    05/11/11 17:50:02 [5208] TRACE [ASTCstaProvider]     sending event:CFTE:CONNCLEARED to xref=1, address=401, callid=2
    05/11/11 17:50:02 [5208] TRACE [TAPIProvider] OnConnectionCleared xref=1 callId=2, releasingDevice=misdn/tmp0-u195 cause=0
    

    In ActivaTSP trunk version it was corrected. I generated a special setup x64 for you that should solve the problem with rename event. ( http://activa.sourceforge.net/temp/setupActivaTSP_x64_test_rename_event.zip )

    I must say we have not tested with Asterisk 1.8, but we think that it may be compatible with ActivaTSP because manager version from 1.6 was no updated.

    Please confirm if that fixes the problem.

    Activa Team.

     
  • andrea

    andrea - 2011-05-25

    Hi,

    Thank you for your reply

    Wonderful!!

    This version has resolved the problem. Now works very well !!!

    It is also possible to test the 32-bit version?

    Andrea

     
  • Anonymous - 2011-06-06

    Hi,
    i have the same problem under 32 bit vista, asterisk 1.4. I am able to place/receive calls from the phone. When outgoing call is placed from the phone or the incoimng call arrives, the events are properly signaled under TAPI application. However, when i place the call from the TAPI app, in this case from system DIALER.EXE, the call fails. First the sip phone is called in. This is expected, as it makes the user to pickup. But after picking up, the number is not called. Instead hangup occurs.
    I have applied the above given temporary version for 32 bit OS, but it seemed not to help. Here is my ActivaTSP log for the situation described. Any help or direction what to change under configuration will be highly appreciated.

    06/06/11 13:24:07  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/06/11 13:24:07  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/06/11 13:24:07  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4f
    06/06/11 13:24:07  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4f
    06/06/11 13:24:19  TRACE  TSPI_lineOpen() dwDeviceID=0x4e htLine=0x102df
    06/06/11 13:24:19  INFO   Connect(192.168.1.135,5038,jarkar9,******)
    06/06/11 13:24:19  TRACE  ASTProvider::SendCommand =>
    Action: Login
    UserName: jarkar9
    Secret: ******
    ActionID: 7

    06/06/11 13:24:19  TRACE  ASTProvider::ReaderProc
    06/06/11 13:24:19  TRACE  Asterisk protocol header: Asterisk Call Manager/1.0
    06/06/11 13:24:19  TRACE   <== asterisk protocol response__________________________
    06/06/11 13:24:19  TRACE  Connect() returns ok
    06/06/11 13:24:19  TRACE  ASTCstaProvider::OpenMonitor device = SIP/1000 => 1000
    06/06/11 13:24:19  TRACE    first monitor for this device: {1000,6}
    06/06/11 13:24:19  TRACE  AddTapiLine xref=6 htapiLine=0x102df pTapiLine=0x41490e0
    06/06/11 13:24:19  TRACE  TSPI_lineGetNumAddressIDs hdLine=00000006
    06/06/11 13:24:19  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/06/11 13:24:19  TRACE  TSPI_lineGetAddressCaps() dwDeviceID=0x4e dwAddressID=0x0
    06/06/11 13:24:19  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/06/11 13:24:19  TRACE  TSPI_lineGetLineDevStatus VOID IMPLEMENTATION
    06/06/11 13:24:19  TRACE  TSPI_lineGetAddressStatus hdLine=00000006
    06/06/11 13:24:19  TRACE  TSPI_lineMakeCall() hdLine=0x6, htCall=0x1017b, phdCall=0x11ae4c0, calledDevice=505020673
    06/06/11 13:24:19  TRACE    filtered calledDevice 505020673 => 505020673
    06/06/11 13:24:19  TRACE   Reading NOANSWERTIMEOUT 0
    06/06/11 13:24:19  TRACE   UserData not found
    06/06/11 13:24:19  TRACE   creating TapiCall 0x414fef8 with htCall 0x1017b
    06/06/11 13:24:19  TRACE  ASTTapiProvider::AddTapiCall pNewTapiCall=0x414fef8 callId=4, htapicall=0x1017b, callerId=SIP/1000, calledId=505020673 userData=
    06/06/11 13:24:19  TRACE    first TapiCall for this callid:  => 0x414fef8
    06/06/11 13:24:19  TRACE   Executing MakeCall
    06/06/11 13:24:19  TRACE  AddConnectionToCallModel {4, SIP/1000} => INITIALIZED
    06/06/11 13:24:19  TRACE   done, now CALL map has 1 items
    06/06/11 13:24:19  TRACE  ASTProvider::Originate call 4 channel:SIP/1000 callerId:SIP/1000 to calledExtension:505020673 in context:from-internal, callerIdName=       timeout=30
    06/06/11 13:24:19  TRACE  ASTProvider::SendCommand =>
    Action: Originate
    Channel: SIP/1000
    Exten: 505020673
    Priority: 1
    Callerid:       #CallId=4 <SIP/1000>
    Context: from-internal
    Variable: originating=SIP/1000
    ActionID: 8
    Timeout: 30000
    Async: 1

    06/06/11 13:24:19  TRACE   <== asterisk protocol response__________________________
    06/06/11 13:24:19  TRACE    Originate success
    06/06/11 13:24:19  TRACE   makecall or makepredictivecall success
    06/06/11 13:24:19  TRACE    NEW callId=4 for htapicall=0x1017b and hdcall=0x11ae4c0
    06/06/11 13:24:19  TRACE    returning dwRequestId 65932
    06/06/11 13:24:19  TRACE  TSPI_lineGetCallInfo: changing callerIDName= by callerId=SIP/1000 because is unknown
    06/06/11 13:24:19  TRACE  TSPI_lineGetCallInfo hdCall=0x414fef8 callerId=SIP/1000, callerIdName=SIP/1000, calledId=505020673, calledIdName=505020673, connectedId=, connectedIdName=, redirectingId=, redirectingIdName=, redirectionId=, userData=, isPredictive=0, dwOrigin=0x10
    06/06/11 13:24:19  TRACE  ASTProvider::HandleEvent => newchannel
    06/06/11 13:24:19  TRACE  OnNewChannelEvent:CFT: ev.m_uniqueId="1307359482.40"; ev.m_callerId="<unknown>"; ev.m_callerIdName="<unknown>"; ev.m_state="Down"; ev.m_channel="SIP/1000-0000001a"; m_pxCstaProvider->OnNewChannelEvent(ev);
    06/06/11 13:24:19  TRACE  Create AsteriskCall with uniqueId = 1307359482.40 and callid =5
    06/06/11 13:24:19  TRACE    setting {1307359482.40}.callerID=, callerIdName=
    06/06/11 13:24:19  TRACE    setting {1307359482.40}.channel=SIP/1000-0000001a, address=1000
    06/06/11 13:24:19  TRACE    state = DOWN => do nothing
    06/06/11 13:24:19  TRACE   <== asterisk protocol event _______________________________
    06/06/11 13:24:19  TRACE  ASTProvider::HandleEvent => newcallerid
    06/06/11 13:24:19  TRACE  OnNewCallerIdEvent:CFT: ev.m_uniqueId="1307359482.40"; ev.m_callerId="SIP/1000"; ev.m_callerIdName="#CallId=4"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    06/06/11 13:24:19  TRACE    overriding {1307359482.40}. to new callerId SIP/1000
    06/06/11 13:24:19  TRACE  Call does not contains UserData
    06/06/11 13:24:19  TRACE  Call containsCallId(4)
    06/06/11 13:24:19  TRACE    overriding {1307359482.40}.5 to new callId 4
    06/06/11 13:24:19  TRACE  Call is NOT predictive
    06/06/11 13:24:19  TRACE   <== asterisk protocol event _______________________________
    06/06/11 13:24:19  TRACE  ASTProvider::HandleEvent => newcallerid
    06/06/11 13:24:19  TRACE  OnNewCallerIdEvent:CFT: ev.m_uniqueId="1307359482.40"; ev.m_callerId="SIP/1000"; ev.m_callerIdName="#CallId=4"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    06/06/11 13:24:19  TRACE  Call does not contains UserData
    06/06/11 13:24:19  TRACE  Call containsCallId(4)
    06/06/11 13:24:19  TRACE    overriding {1307359482.40}.4 to new callId 4
    06/06/11 13:24:19  TRACE  Call is NOT predictive
    06/06/11 13:24:19  TRACE   <== asterisk protocol event _______________________________
    06/06/11 13:24:19  TRACE  TSPI_lineGetCallInfo: changing callerIDName= by callerId=SIP/1000 because is unknown
    06/06/11 13:24:19  TRACE  TSPI_lineGetCallInfo hdCall=0x414fef8 callerId=SIP/1000, callerIdName=SIP/1000, calledId=505020673, calledIdName=505020673, connectedId=, connectedIdName=, redirectingId=, redirectingIdName=, redirectionId=, userData=, isPredictive=0, dwOrigin=0x10
    06/06/11 13:24:19  TRACE  TSPI_lineGetCallStatus
    06/06/11 13:24:19  TRACE  ASTProvider::HandleEvent => newstate
    06/06/11 13:24:19  TRACE  OnNewStateEvent:CFT: ev.m_uniqueId="1307359482.40"; ev.m_callerIdName="#CallId=4"; ev.m_state="Ringing"; ev.m_channel="SIP/1000-0000001a"; m_pxCstaProvider->OnNewStateEvent(ev);
    06/06/11 13:24:19  TRACE  Call does not contains UserData
    06/06/11 13:24:19  TRACE  Call containsCallId(4)
    06/06/11 13:24:19  TRACE    overriding {1307359482.40}.4 to new callId 4
    06/06/11 13:24:19  TRACE  Call is NOT predictive
    06/06/11 13:24:19  TRACE    setting {1307359482.40}.callerID=SIP/1000, callerIdName=
    06/06/11 13:24:19  TRACE    state = RINGING => Send ALERTING to {1307359482.40}.address=1000
    06/06/11 13:24:19  TRACE  ASTCstaProvider::handleConnectionAlerting uniqueId=1307359482.40, address=1000
    06/06/11 13:24:19  TRACE  ASTCallMap::GetSourceCall(0x41498c8)
    06/06/11 13:24:19  TRACE    SourceCall is 1307359482.40
    06/06/11 13:24:19  TRACE  GetCIDInfoFromSourceCall(1307359482.40)
    06/06/11 13:24:19  TRACE    Exiting with cid/cidname/userData=SIP/1000//
    06/06/11 13:24:19  TRACE  AddConnectionToCallModel {4, 1000} => ALERTING
    06/06/11 13:24:19  TRACE   done, now CALL map has 1 items
    06/06/11 13:24:19  TRACE    event minimization RULE-4: (callerid = SIP/1000) == (called = SIP/1000) == (address = 1000)
    06/06/11 13:24:19  TRACE   <== asterisk protocol event _______________________________
    06/06/11 13:24:21  TRACE  ASTProvider::HandleEvent => newstate

     
  • activatsp

    activatsp - 2011-06-09

    Hi!

    The log is incomplete, the reason is probably the trace buffering…
    Please reproduce the problem and wait until Hangup events appear in the log file.

    ActivaTeam.

     
  • Anonymous - 2011-06-10

    Hi, thanks for the response, i will test it right now again and wait longer before i copy the log. Hopefully i can have all evebts catched. I didnt want to give you more events than necesary, to make the situation clean. So, i contact shortly

     
  • Anonymous - 2011-06-10

    Hi again, hope it is complete now.
    Its not excluded, that my asterisk configuration is not perfect. I am very new to asterisk. I would like to connect our Windows TAPI based apps with asterisk. Thanks aganin in advance for your effort.
    Jarek

    06/10/11 17:04:24  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/10/11 17:04:24  TRACE  TSPI_lineGetAddressCaps() dwDeviceID=0x4e dwAddressID=0x0
    06/10/11 17:04:24  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4f
    06/10/11 17:04:24  TRACE  TSPI_lineGetAddressCaps() dwDeviceID=0x4f dwAddressID=0x0
    06/10/11 17:04:44  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/10/11 17:04:44  TRACE  TSPI_lineGetAddressCaps() dwDeviceID=0x4e dwAddressID=0x0
    06/10/11 17:04:44  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4f
    06/10/11 17:04:44  TRACE  TSPI_lineGetAddressCaps() dwDeviceID=0x4f dwAddressID=0x0
    06/10/11 17:06:21  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/10/11 17:06:21  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/10/11 17:06:21  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4f
    06/10/11 17:06:21  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4f
    06/10/11 17:06:26  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/10/11 17:06:26  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/10/11 17:06:26  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4f
    06/10/11 17:06:26  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4f
    06/10/11 17:06:43  TRACE  TSPI_lineOpen() dwDeviceID=0x4e htLine=0x10278
    06/10/11 17:06:43  INFO   Connect(192.168.1.135,5038,jarkar9,*******)
    06/10/11 17:06:44  TRACE  ASTProvider::ReaderProc
    06/10/11 17:06:44  TRACE  ASTProvider::SendCommand =>
    Action: Login
    UserName: jarkar9
    Secret: *******
    ActionID: 1

    06/10/11 17:06:44  TRACE  Asterisk protocol header: Asterisk Call Manager/1.0
    06/10/11 17:06:44  TRACE   <== asterisk protocol response__________________________
    06/10/11 17:06:44  TRACE  Connect() returns ok
    06/10/11 17:06:44  TRACE  ASTCstaProvider::OpenMonitor device = SIP/1000 => 1000
    06/10/11 17:06:44  TRACE    first monitor for this device: {1000,1}
    06/10/11 17:06:44  TRACE  AddTapiLine xref=1 htapiLine=0x10278 pTapiLine=0x6491f20
    06/10/11 17:06:44  TRACE  TSPI_lineGetNumAddressIDs hdLine=00000001
    06/10/11 17:06:44  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/10/11 17:06:44  TRACE  TSPI_lineGetAddressCaps() dwDeviceID=0x4e dwAddressID=0x0
    06/10/11 17:06:44  TRACE  TSPI_lineGetDevCaps() dwDeviceIdBase=0x4e dwDeviceID=0x4e
    06/10/11 17:06:44  TRACE  TSPI_lineGetLineDevStatus VOID IMPLEMENTATION
    06/10/11 17:06:44  TRACE  TSPI_lineGetAddressStatus hdLine=00000001
    06/10/11 17:06:45  TRACE  TSPI_lineMakeCall() hdLine=0x1, htCall=0x102bd, phdCall=0x74f310, calledDevice=505020673
    06/10/11 17:06:45  TRACE    filtered calledDevice 505020673 => 505020673
    06/10/11 17:06:45  TRACE   Reading NOANSWERTIMEOUT 0
    06/10/11 17:06:45  TRACE   UserData not found
    06/10/11 17:06:45  TRACE   creating TapiCall 0x3f9f720 with htCall 0x102bd
    06/10/11 17:06:45  TRACE  ASTTapiProvider::AddTapiCall pNewTapiCall=0x3f9f720 callId=2, htapicall=0x102bd, callerId=SIP/1000, calledId=505020673 userData=
    06/10/11 17:06:45  TRACE    first TapiCall for this callid:  => 0x3f9f720
    06/10/11 17:06:45  TRACE   Executing MakeCall
    06/10/11 17:06:45  TRACE  AddConnectionToCallModel {2, SIP/1000} => INITIALIZED
    06/10/11 17:06:45  TRACE   done, now CALL map has 1 items
    06/10/11 17:06:45  TRACE  ASTProvider::Originate call 2 channel:SIP/1000 callerId:SIP/1000 to calledExtension:505020673 in context:from-internal, callerIdName=       timeout=30
    06/10/11 17:06:45  TRACE  ASTProvider::SendCommand =>
    Action: Originate
    Channel: SIP/1000
    Exten: 505020673
    Priority: 1
    Callerid:       #CallId=2 <SIP/1000>
    Context: from-internal
    Variable: originating=SIP/1000
    ActionID: 2
    Timeout: 30000
    Async: 1

    06/10/11 17:06:45  TRACE   <== asterisk protocol response__________________________
    06/10/11 17:06:45  TRACE    Originate success
    06/10/11 17:06:45  TRACE   makecall or makepredictivecall success
    06/10/11 17:06:45  TRACE    NEW callId=2 for htapicall=0x102bd and hdcall=0x74f310
    06/10/11 17:06:45  TRACE    returning dwRequestId 66220
    06/10/11 17:06:45  TRACE  ASTProvider::HandleEvent => newchannel
    06/10/11 17:06:45  TRACE  OnNewChannelEvent:CFT: ev.m_uniqueId="1307718449.2"; ev.m_callerId="<unknown>"; ev.m_callerIdName="<unknown>"; ev.m_state="Down"; ev.m_channel="SIP/1000-00000002"; m_pxCstaProvider->OnNewChannelEvent(ev);
    06/10/11 17:06:45  TRACE  TSPI_lineGetCallInfo: changing callerIDName= by callerId=SIP/1000 because is unknown
    06/10/11 17:06:45  TRACE  TSPI_lineGetCallInfo hdCall=0x3f9f720 callerId=SIP/1000, callerIdName=SIP/1000, calledId=505020673, calledIdName=505020673, connectedId=, connectedIdName=, redirectingId=, redirectingIdName=, redirectionId=, userData=, isPredictive=0, dwOrigin=0x10
    06/10/11 17:06:45  TRACE  Create AsteriskCall with uniqueId = 1307718449.2 and callid =3
    06/10/11 17:06:45  TRACE    setting {1307718449.2}.callerID=, callerIdName=
    06/10/11 17:06:45  TRACE    setting {1307718449.2}.channel=SIP/1000-00000002, address=1000
    06/10/11 17:06:45  TRACE    state = DOWN => do nothing
    06/10/11 17:06:45  TRACE   <== asterisk protocol event _______________________________
    06/10/11 17:06:45  TRACE  ASTProvider::HandleEvent => newcallerid
    06/10/11 17:06:45  TRACE  OnNewCallerIdEvent:CFT: ev.m_uniqueId="1307718449.2"; ev.m_callerId="SIP/1000"; ev.m_callerIdName="#CallId=2"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    06/10/11 17:06:45  TRACE    overriding {1307718449.2}. to new callerId SIP/1000
    06/10/11 17:06:45  TRACE  Call does not contains UserData
    06/10/11 17:06:45  TRACE  Call containsCallId(2)
    06/10/11 17:06:45  TRACE    overriding {1307718449.2}.3 to new callId 2
    06/10/11 17:06:45  TRACE  Call is NOT predictive
    06/10/11 17:06:45  TRACE   <== asterisk protocol event _______________________________
    06/10/11 17:06:45  TRACE  ASTProvider::HandleEvent => newcallerid
    06/10/11 17:06:45  TRACE  OnNewCallerIdEvent:CFT: ev.m_uniqueId="1307718449.2"; ev.m_callerId="SIP/1000"; ev.m_callerIdName="#CallId=2"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
    06/10/11 17:06:45  TRACE  Call does not contains UserData
    06/10/11 17:06:45  TRACE  Call containsCallId(2)
    06/10/11 17:06:45  TRACE    overriding {1307718449.2}.2 to new callId 2
    06/10/11 17:06:45  TRACE  Call is NOT predictive
    06/10/11 17:06:45  TRACE   <== asterisk protocol event _______________________________
    06/10/11 17:06:45  TRACE  ASTProvider::HandleEvent => newstate
    06/10/11 17:06:45  TRACE  OnNewStateEvent:CFT: ev.m_uniqueId="1307718449.2"; ev.m_callerIdName="#CallId=2"; ev.m_state="Ringing"; ev.m_channel="SIP/1000-00000002"; m_pxCstaProvider->OnNewStateEvent(ev);
    06/10/11 17:06:45  TRACE  Call does not contains UserData
    06/10/11 17:06:45  TRACE  Call containsCallId(2)
    06/10/11 17:06:45  TRACE    overriding {1307718449.2}.2 to new callId 2
    06/10/11 17:06:45  TRACE  Call is NOT predictive
    06/10/11 17:06:45  TRACE    setting {1307718449.2}.callerID=SIP/1000, callerIdName=
    06/10/11 17:06:45  TRACE    state = RINGING => Send ALERTING to {1307718449.2}.address=1000
    06/10/11 17:06:45  TRACE  ASTCstaProvider::handleConnectionAlerting uniqueId=1307718449.2, address=1000
    06/10/11 17:06:45  TRACE  ASTCallMap::GetSourceCall(0x3f9faa8)
    06/10/11 17:06:45  TRACE    SourceCall is 1307718449.2
    06/10/11 17:06:45  TRACE  GetCIDInfoFromSourceCall(1307718449.2)
    06/10/11 17:06:45  TRACE    Exiting with cid/cidname/userData=SIP/1000//
    06/10/11 17:06:45  TRACE  AddConnectionToCallModel {2, 1000} => ALERTING
    06/10/11 17:06:45  TRACE   done, now CALL map has 1 items
    06/10/11 17:06:45  TRACE    event minimization RULE-4: (callerid = SIP/1000) == (called = SIP/1000) == (address = 1000)
    06/10/11 17:06:45  TRACE   <== asterisk protocol event _______________________________
    06/10/11 17:06:45  TRACE  TSPI_lineGetCallInfo: changing callerIDName= by callerId=SIP/1000 because is unknown
    06/10/11 17:06:45  TRACE  TSPI_lineGetCallInfo hdCall=0x3f9f720 callerId=SIP/1000, callerIdName=SIP/1000, calledId=505020673, calledIdName=505020673, connectedId=, connectedIdName=, redirectingId=, redirectingIdName=, redirectionId=, userData=, isPredictive=0, dwOrigin=0x10
    06/10/11 17:06:45  TRACE  TSPI_lineGetCallStatus
    06/10/11 17:06:52  TRACE  ASTProvider::HandleEvent => newstate
    06/10/11 17:06:52  TRACE  OnNewStateEvent:CFT: ev.m_uniqueId="1307718449.2"; ev.m_callerIdName="#CallId=2"; ev.m_state="Up"; ev.m_channel="SIP/1000-00000002"; m_pxCstaProvider->OnNewStateEvent(ev);
    06/10/11 17:06:52  TRACE  Call does not contains UserData
    06/10/11 17:06:52  TRACE  Call containsCallId(2)
    06/10/11 17:06:52  TRACE  Call is NOT predictive
    06/10/11 17:06:52  TRACE    setting {1307718449.2}.callerID=SIP/1000, callerIdName=
    06/10/11 17:06:52  TRACE    state = UP => Send ESTABLISHED to {1307718449.2}.address=1000
    06/10/11 17:06:52  TRACE  ASTCstaProvider::handleConnectionConnected uniqueId=1307718449.2, address=1000
    06/10/11 17:06:52  TRACE  ASTCallMap::GetSourceCall(0x3f9faa8)
    06/10/11 17:06:52  TRACE    SourceCall is 1307718449.2
    06/10/11 17:06:52  TRACE  GetCIDInfoFromSourceCall(1307718449.2)
    06/10/11 17:06:52  TRACE    Exiting with cid/cidname/userData=SIP/1000//
    06/10/11 17:06:52  TRACE  AddConnectionToCallModel {2, 1000} => CONNECTED
    06/10/11 17:06:52  TRACE   done, now CALL map has 1 items
    06/10/11 17:06:52  TRACE    event minimization RULE-4: (callerid = SIP/1000) == (called = SIP/1000) == (address = 1000)
    06/10/11 17:06:52  TRACE   <== asterisk protocol event _______________________________
    06/10/11 17:06:52  TRACE  ASTProvider::HandleEvent => originateresponse
    06/10/11 17:06:52  TRACE   <== asterisk protocol event _______________________________
    06/10/11 17:06:52  TRACE  ASTProvider::HandleEvent => hangup
    06/10/11 17:06:52  TRACE  OnHangup:CFT: ev.m_uniqueId="1307718449.2"; ev.m_cause="16"; m_pxCstaProvider->OnHangupEvent(ev);
    06/10/11 17:06:52  TRACE  GetStateOfDevice {2, 1000}
    06/10/11 17:06:52  TRACE     deviceState = CONNECTED
    06/10/11 17:06:52  TRACE    handleConnectionDisconnected {1307718449.2} to 1000
    06/10/11 17:06:52  TRACE  ASTCallMap::GetLogicAddress(0x3f9faa8)
    06/10/11 17:06:52  TRACE  ASTCstaProvider::handleConnectionDisconnected uniqueId=1307718449.2, logicaddress=1000, cause=0
    06/10/11 17:06:52  TRACE  GetMonitorSetFromCallModel = 2
    06/10/11 17:06:52  TRACE    num_monitors = 1
    06/10/11 17:06:52  TRACE      sending event:CFTE:CONNCLEARED to xref=1, address=1000, callid=2
    06/10/11 17:06:52  TRACE  OnConnectionCleared xref=1 callId=2, releasingDevice=1000 cause=0
    06/10/11 17:06:52  TRACE   searching a TapiCall with callId 2 in tapiLine 0x6491f20
    06/10/11 17:06:52  TRACE      htapiline=0x10278, deviceID=SIP/1000, htapicall=0x102bd, releasingDevice=1000, callerid=N/A, callerIdName=N/A, calleddevice=N/A, lastRedirection=N/A
    06/10/11 17:06:52  TRACE    LINECALLSTATE_IDLE NORMAL htapicall=0x102bd
    06/10/11 17:06:52  TRACE  RemoveConnection {2}=> 1000
    06/10/11 17:06:52  TRACE    removed uniqueId=1307718449.2 call from MAP
    06/10/11 17:06:52  TRACE    handleCallDisconnected {2} was the last one
    06/10/11 17:06:52  TRACE  GetMonitorSetFromCallModel = 2
    06/10/11 17:06:52  TRACE    num_monitors = 1
    06/10/11 17:06:52  TRACE      sending event:CFTE:CALLCLEARED to xref=1, callid=2
    06/10/11 17:06:52  TRACE  OnCallCleared xref=1 callId=2 userData= cause=0
    06/10/11 17:06:52  TRACE   searching a TapiCall with callId 2 in tapiLine 0x6491f20
    06/10/11 17:06:52  TRACE  don't send events because call is idle
    06/10/11 17:06:52  TRACE  RemoveCall {2}
    06/10/11 17:06:52  TRACE    removed entry with callId=2 from MAP
    06/10/11 17:06:52  TRACE   <== asterisk protocol event _______________________________
    06/10/11 17:06:52  TRACE  TSPI_lineGetCallStatus
    06/10/11 17:06:52  TRACE  TSPI_lineGetCallInfo: changing callerIDName= by callerId=SIP/1000 because is unknown
    06/10/11 17:06:52  TRACE  TSPI_lineGetCallInfo hdCall=0x3f9f720 callerId=SIP/1000, callerIdName=SIP/1000, calledId=505020673, calledIdName=505020673, connectedId=, connectedIdName=, redirectingId=SIP/1000, redirectingIdName=SIP/1000, redirectionId=, userData=, isPredictive=0, dwOrigin=0x10
    06/10/11 17:07:01  TRACE  TSPI_lineCloseCall() hdCall=0x3f9f720
    06/10/11 17:07:01  TRACE  ASTTapiProvider::RemoveTapiCall hdrivercall=0x3f9f720
    06/10/11 17:07:01  TRACE    call had callid=2
    06/10/11 17:07:01  TRACE      …with 1 associated hdrvrcalls
    06/10/11 17:07:01  TRACE    delete htcall 0x102bd and hdrvCall 0x3f9f720
    06/10/11 17:07:01  TRACE    deleted the last htapicall and the set of callid 2
    06/10/11 17:07:01  TRACE    deleting pTapiCall addrs=SIP/1000 htapiCall=0x102bd
    06/10/11 17:07:02  TRACE  TSPI_lineClose() hdLine=0x1
    06/10/11 17:07:02  TRACE  RemoveTapiLine hdrvLine=0x1
    06/10/11 17:07:02  TRACE    was SIP/1000
    06/10/11 17:07:02  TRACE  ASTCstaProvider::CloseMonitor xref = 1
    06/10/11 17:07:02  TRACE    erase xref map entry
    06/10/11 17:07:02  TRACE      erase extension map entry
    06/10/11 17:07:02  TRACE    return 1!
    06/10/11 17:07:02  INFO   Disconnect socked and clear callmaps because no line is open.
    06/10/11 17:07:02  INFO   Socket recv code = -1
    06/10/11 17:07:02  INFO   Error code 10053, The virtual circuit was terminated due to a time-out or other failure. The application should close the socket as it is no longer usable.
    06/10/11 17:07:02  TRACE  ASTProvider::ReaderProc EXITS
    06/10/11 17:07:02  INFO   Socket closed without errors.
    06/10/11 17:07:02  TRACE  WaitReaderThread => Thread terminated nicely

    06/10/11 17:07:02  TRACE   CallMapCleanup() cleaning maps

     
  • activatsp

    activatsp - 2011-06-14

    Hi!

    In the log I can apreciate that the call was hangup with cause 16 => "Normal".

    17:06:52 [13588] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup 
    17:06:52 [13588] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1307718449.2"; ev.m_cause="16"; m_pxCstaProvider->OnHangupEvent(ev);
    

    Now we need to known why the call was hangup by Asterisk, the best way to do this is accessing the Asterisk Cli (http://www.voip-info.org/wiki/view/Asterisk+CLI) and set verbose (core set verbose 3), then do the test and asterisk will print some verbose information to the cli console, I hope in this verbose information we can find the cause of the problem.

    We know that some asterisk 1.6.2 versions had a bug and can't originate calls (https://issues.asterisk.org/view.php?id=16729).

    Be sure that 505020673@from-internal is set in your dialplan, you can test it executing "dialplan show 505020673@from-internal" from the Asterisk CLI.

    Activa Team.

     
  • Anonymous - 2011-06-14

    Hi,
    thanks for your answer. Unfortunately i dont know much dialplans of asterisk. But i am sure the 505020673 is NOT in the dialplan. As it is an external number, i didnt thought, every single external number needs to be in my dialplan. This is an outgoing call made from internal line: 1000. Maybe instead of 505020673 is it possible to setup a general phonenumber mask with some wildcards. I will show you my dialplan from extensions.conf soon. Maybe you could suggest me what to change. This would be great.
    Jarek

     
  • Anonymous - 2011-06-14

    Hi again,
    below is my simple configuration from files extensions.conf and sip.conf. Unfortunately i dont know, if it right or not. But it works when calling from sip phones 1000 or 1001 to external phone numbers through my provider. Incoming call are signaled properly as well, but in this case also tapi works fine.
    maybe some changes would be suggested. under TSP settings context is set to from-internal. IIRC i also tried to use e-call-out as a context. But it didnt work at all.
    extensions.conf


    exten => _.,1,Hangup

    exten => t,1,Hangup
    exten => h,1,Hangup
    exten => _X.,1,SIPAddHeader(X-Fid: ${223791734})
    exten => _X.,2,Dial(sip/${EXTEN}@e-call-out)
    exten => 223791734,1,Dial(SIP/1000,45,Tt)

    sip.conf

    exten => _XXXX,1,Dial(SIP/${EXTEN})
    exten => _1000,1,Dial(SIP/${EXTEN})
    exten => _1001,1,Dial(SIP/${EXTEN})

    context=default
    defaultexpiry=60
    allowguest=no
    dtmfmode=rfc2833
    nat=yes
    localnet=192.168.1.135/255.255.255.0
    externip=************
    register => 223791734:*********@ositron.e-call.pl/223791734

    type=peer
    username=223791734
    secret=***********
    fromdomain=ositron.e-call.pl
    context=e-call
    host=ositron.e-call.pl
    port=5060
    fromuser=223791734
    authuser=223791734
    outboundproxy=ositron.e-call.pl
    outboundproxyport=5060
    insecure=no
    dtmf=inband

    type=peer
    fromdomain=ositron.e-call.pl
    port=5060
    context=e-call
    host=ositron.e-call.pl
    insecure=no

    Jarek

     
  • activatsp

    activatsp - 2011-06-15

    Hi,

    please, read last post again, I think the helpful way is:

    Now we need to known why the call was hangup by Asterisk, the best way to do this is accessing the Asterisk Cli (http://www.voip-info.org/wiki/view/Asterisk+CLI) and set verbose (core set verbose 3), then do the test and asterisk will print some verbose information to the cli console, I hope in this verbose information we can find the cause of the problem.
    

    When I say:

    Be sure that 505020673@from-internal is set in your dialplan, you can test it executing "dialplan show 505020673@from-internal" from the Asterisk CLI.
    

    I sugested to login to a linux prompt, and then access to the asterisk CLI (executing asterisk-vvvr) and from the asterisk CLI execute "dialplan show 505020673@from-internal" and Asterisk will show you the dialplan executed when 505020673@from-internal including the willcard extensions defined.

    Example:
    [ Included context 'bad-number' created by 'pbx_config' ]
      '_X.' =>          1. ResetCDR()                                 [pbx_config]
                        2. NoCDR()                                    [pbx_config]
                        3. Wait(1)                                    [pbx_config]
                        4. Playback(silence/1&cannot-complete-as-dialed&check-number-dial-again|noanswer) [pbx_config]
                        5. Wait(1)                                    [pbx_config]
                        6. Congestion(20)                             [pbx_config]
                        7. Hangup()                                   [pbx_config]
    

    Seeing your dialplan, it seems that you expect the call between the context "e-call", but in activaTSP's configuration there is "from-internal", ¿Could be this the error?

    Activa Team

     
  • Anonymous - 2011-06-17

    Hi Activa Team,
    changing context to e-call in my TSP settings solved the problem.
    Thank you very much for your help. TSP works fine now.

    However i have some question related to TSP itself.
    Why you deploy the TSP file into Windows directory? The common directory for TSP files is Windows system directory. Advantage is following: if you for example remove TSP from modem/phone applet, without deinstalling TSP, you can simply add it every time. But in case of ActivaTSP one has to reinstall the package or move manual the TSP file to system directory.

     
  • activatsp

    activatsp - 2011-07-26

    Hi all,

    SetupActivaTSP_test_rename_event.zip was deleted from his temporal location, ActivaTSP-1.8.0 was released and adds the fix reffered by this post, please update to ActivaTSP-1.8.0:

        New: Asterisk 1.8 compatibility (tested 1.8.5.0 using new parameters connectedLineNum/Name).
        New: Configurable Originate Variables ussing Dialog.
        NEW: Login MD5 AuthType.
        NEW: Dn edit replaced by a TextArea, limeted to 255 chars.
        NEW: Logging dialog configuration parameters.
        NEW: ActivaAPI library, that publish the C++ Activa's CSTA model for Asterisk AMI.
        NEW: Universal Queue specific tests.
        Fix: Keep logFilePath after update install.
        FIX: Configure VC projects to use Multi-threaded DLL runtime.
        FIX: DialPlan Dial to local channels isn't handled properly.
        Fix: Don't send ConnCleared OnRenameEvent.
        Fix: Don't count initialized devices when doing Fasttransfer.
        Fix: Possible Av. Use only once negative return code ussing CompletionProc or "TSPI return code".
        Fix: If Dial / NewState Ringing events come disordered alerting / established were reported ussing different callid.
        Fix: Dn expresion max len extended to 256.
        Fix: Duplicate alerting in predictive calls.
        FIX: Install vcredist for VC2005sp1 at install time.

    ActivaTeam.

     

Get latest updates about Open Source Projects, Conferences and News.

Sign up for the SourceForge newsletter:





No, thanks