Call Drops if the multiple devices dialed

[Chris Baker]

We have our asterisk 1.8.7.1 configured for each extension to dial multiple extensions, for example 2706, will ring at 2706s and 2706.  For example here is the dial command: Dial("Local/2705@internal-6c42;2", "SIP/2705&SIP/2705s,15,tTwW")
Whenever there are multiple extensions being dialed the call gets dropped.   If there is only one extension being dialed like (Dial("Local/2705@internal-6c42;2", "SIP/2705,15,tTwW") then the call succeeds.   The dialplan itself is working fine, the problem only happens when the call is placed using activa tsp. 
activa configuration:
agentContext: internal
AuthType 1
dn0 2705
dnprefix AST
host Asterisk's ip address
OriginateVariable 2705
outgoing context: internal
password: ourpassword
user: ouramiuser
Below is the log file from Activa TSP Any ideas?

01/31/12 14:08:19 [3948] TRACE [TAPIProvider] TSPI_lineGetDevCaps() dwDeviceIdBase=0x5 dwDeviceID=0x5
01/31/12 14:08:19 [3948] TRACE [TAPIProvider] TSPI_lineGetAddressCaps() dwDeviceID=0x5 dwAddressID=0x0
01/31/12 14:09:32 [6664] TRACE [TAPIProvider] TSPI_lineOpen() dwDeviceID=0x5 htLine=0x100bb
01/31/12 14:09:32 [6664] INFO  [ASTProvider] Connect(10.0.0.141,5038,fop2,1234fixedb!d)
01/31/12 14:09:32 [6664] TRACE [ASTProvider] ASTProvider::SendCommand => 
Action: Challenge
AuthType: MD5
ActionID: 20
01/31/12 14:09:32 [6308] TRACE [ASTProvider] ASTProvider::ReaderProc
01/31/12 14:09:32 [6308] TRACE [ASTProvider] Asterisk protocol header: Asterisk Call Manager/1.1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: response DATA: Success
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: actionid DATA: 20
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: challenge DATA: 135966958
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol response__________________________
01/31/12 14:09:32 [6664] TRACE [ASTProvider] ASTProvider::SendCommand => 
Action: Login
AuthType: MD5
UserName: fop2
Key: f8e2eaae9b3da05a3d06aef035bc2ed8
ActionID: 20
01/31/12 14:09:32 [6664] TRACE [ASTProvider] Connect() returns ok
01/31/12 14:09:32 [6664] TRACE [ASTCstaProvider] ASTCstaProvider::OpenMonitor device = 2706 => 2706
01/31/12 14:09:32 [6664] TRACE [ASTCallMap]   first monitor for this device: {2706,7}
01/31/12 14:09:32 [6664] TRACE [TAPIProvider] AddTapiLine xref=7 htapiLine=0x100bb pTapiLine=0xba39b30
01/31/12 14:09:32 [6664] TRACE [TSP] TSPI_lineGetNumAddressIDs hdLine=0000000000000007
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: response DATA: Success
01/31/12 14:09:32 [6664] TRACE [TAPIProvider] TSPI_lineMakeCall() hdLine=0x7, htCall=0x10099, phdCall=0x1f55f48, calledDevice=T2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: actionid DATA: 20
01/31/12 14:09:32 [6664] TRACE0[TAPIProvider] EncodedString 'T2710' does not contain the key:#FEATURE=
01/31/12 14:09:32 [6664] TRACE0[TAPIProvider] Value for key #FEATURE= isn't found then assign default value = 
01/31/12 14:09:32 [6664] TRACE [TAPIProvider]   filtered calledDevice T2710 => 2710
01/31/12 14:09:32 [6664] TRACE [TAPIProvider]  Reading NOANSWERTIMEOUT 0
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: message DATA: Authentication accepted
01/31/12 14:09:32 [6664] TRACE [TAPIProvider]  UserData not found
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol response__________________________
01/31/12 14:09:32 [6664] TRACE [TAPIProvider]  creating TapiCall 0xb9a47d0 with htCall 0x10099
01/31/12 14:09:32 [6664] TRACE [TAPIProvider] ASTTapiProvider::AddTapiCall pNewTapiCall=0xb9a47d0 callId=39, htapicall=0x10099, callerId=2706, calledId=2710 userData=
01/31/12 14:09:32 [6664] TRACE [TAPIProvider]   first TapiCall for this callid: [39] => 0xb9a47d0
01/31/12 14:09:32 [6664] TRACE0[TAPIProvider] ================================================================= start callmap dump...
01/31/12 14:09:32 [6664] TRACE0[TAPIProvider] DUMP OF TSP CALLS MAP: [HDRVCALL] => call info:
01/31/12 14:09:32 [6664] TRACE0[TAPIProvider]   [0xb9a47d0] TapiLine=0x000000000BA39B30 hdrivercall=0x000000000B9A47D0 htapicall=0x0000000000010099 callID=39 address=2706 state= CID=2706 CIDName= lastRedir= called=2710 userData= isPredictive=0 cause=0
01/31/12 14:09:32 [6664] TRACE0[TAPIProvider] DUMP OF CALL-ID MAP: {CALL_ID} => hdrivercall
01/31/12 14:09:32 [6664] TRACE0[TAPIProvider]       [39] => TapiLine=0x000000000BA39B30 hdrivercall=0x000000000B9A47D0 htapicall=0x0000000000010099 callID=39 address=2706 state= CID=2706 CIDName= lastRedir= called=2710 userData= isPredictive=0 cause=0
01/31/12 14:09:32 [6664] TRACE0[TAPIProvider] ================================================================= end callmap dump...
01/31/12 14:09:32 [6664] TRACE [TAPIProvider]  Executing MakeCall
01/31/12 14:09:32 [6664] TRACE0[ASTCallMap] ================================================================= start callmap dump...
01/31/12 14:09:32 [6664] TRACE0[ASTCallMap] DUMP OF ASTERISK CALLS MAP: {UNIQUEID} => call info:
01/31/12 14:09:32 [6664] TRACE0[ASTCallMap] DUMP OF MONITOR CALLS MAP: {CALL_ID} => DEVICE: => STATE
01/31/12 14:09:32 [6664] TRACE0[ASTCallMap] ================================================================= end callmap dump...
01/31/12 14:09:32 [6664] TRACE [ASTCallMap] AddConnectionToCallModel {39, 2706} => INITIALIZED
01/31/12 14:09:32 [6664] TRACE [ASTCallMap]  done, now CALL map has 1 items
01/31/12 14:09:32 [6664] TRACE [ASTProvider] ASTProvider::Originate call 39 channel:Local/2706@internal callerId:2706 to calledExtension:2710 in context:internal, callerIdName=Andy rudd       timeout=30
01/31/12 14:09:32 [6664] TRACE [ASTProvider] ASTProvider::SendCommand => 
Action: Originate
Channel: Local/2706@internal/n
Exten: 2710
Priority: 1
Callerid: Andy rudd      #Id=39 <2706>
Context: internal
Variable: originating=2706,2706
ActionID: 21
Timeout: 30000
Async: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: FullyBooted
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: status DATA: Fully Booted
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => fullybooted
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: response DATA: Success
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: actionid DATA: 21
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: message DATA: Originate successfully queued
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol response__________________________
01/31/12 14:09:32 [6664] TRACE [ASTProvider]   Originate success
01/31/12 14:09:32 [6664] TRACE [TAPIProvider]  makecall or makepredictivecall success
01/31/12 14:09:32 [6664] TRACE0[TAPIProvider] CompletionProc Done and the reader was unlocked
01/31/12 14:09:32 [6664] TRACE [TAPIProvider]   NEW callId=39 for htapicall=0x10099 and hdcall=0x1f55f48
01/31/12 14:09:32 [6664] TRACE [TAPIProvider]   returning dwRequestId 65706
01/31/12 14:09:32 [1616] TRACE [TAPIProvider] TSPI_lineGetCallInfo: changing callerIDName= by callerId=2706 because is unknown
01/31/12 14:09:32 [1616] TRACE [TAPIProvider] TSPI_lineGetCallInfo hdCall=0xb9a47d0 callerId=2706, callerIdName=2706, calledId=2710, calledIdName=2710, connectedId=, connectedIdName=, redirectingId=, redirectingIdName=, redirectionId=, userData=, isPredictive=0, dwOrigin=0x10
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newchannel
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 0
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Down
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: accountcode DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1328036973.683"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Down"; ev.m_channel="Local/2706@internal-4305;1"; m_pxCstaProvider->OnNewChannelEvent(ev);
01/31/12 14:09:32 [6308] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1328036973.683 and callid =40
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683}.callerID=, callerIdName=
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683}.channel=Local/2706@internal-4305;1, address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   state = DOWN => do nothing
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newchannel
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 4
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Ring
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: accountcode DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:32 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1328036973.684"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Ring"; ev.m_channel="Local/2706@internal-4305;2"; m_pxCstaProvider->OnNewChannelEvent(ev);
01/31/12 14:09:32 [6308] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1328036973.684 and callid =41
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684}.callerID=, callerIdName=
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684}.channel=Local/2706@internal-4305;2, address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]  link call {1328036973.684} with call {1328036973.683}
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   state = RING => Send ORIGINATED to {1328036973.684}.address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionOriginated uniqueId=1328036973.684, address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: originating
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: NewCallerid
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: cid-callingpres DATA: 0 (Presentation Allowed, Not Screened)
01/31/12 14:09:32 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1328036973.683"; ev.m_callerId="2706"; ev.m_callerIdName="Andy rudd      #Id=39"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.683}. to new callerId 2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.683}.40 to new callId 39
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.683}. to new calleridname Andy rudd      
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: NewAccountCode
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: accountcode DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: oldaccountcode DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newaccountcode
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: NewCallerid
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: cid-callingpres DATA: 0 (Presentation Allowed, Not Screened)
01/31/12 14:09:32 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1328036973.683"; ev.m_callerId="2706"; ev.m_callerIdName="Andy rudd      #Id=39"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.683}.39 to new callId 39
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.683}.Andy rudd       to new calleridname Andy rudd      
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Answer
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 6
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Up
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.683"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Up"; ev.m_channel="Local/2706@internal-4305;1"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683}.callerID=2706, callerIdName=Andy rudd      
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683} ConnectedLineNum=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1328036973.683}.address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1328036973.683, address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xb9a5e10)
01/31/12 14:09:32 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: OriginateResponse
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: actionid DATA: 21
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: response DATA: Success
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: reason DATA: 4
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => originateresponse
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 6
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Up
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:32 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.684"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Up"; ev.m_channel="Local/2706@internal-4305;2"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684}.callerID=, callerIdName=Andy rudd      
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684} ConnectedLineNum=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1328036973.684}.address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1328036973.684, address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xba38e00)
01/31/12 14:09:32 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Answer
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 2
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Ringing
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 5
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Ringing
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:32 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.684"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Ringing"; ev.m_channel="Local/2706@internal-4305;2"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.684}.41 to new callId 39
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684}.callerID=, callerIdName=Andy rudd      
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684} ConnectedLineNum=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1328036973.684}.address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1328036973.684, address=2706
01/31/12 14:09:32 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xba38e00)
01/31/12 14:09:32 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xba38e00)
01/31/12 14:09:32 [6308] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
01/31/12 14:09:32 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 3
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: CALLTIME=20120131140933
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: CALLTIME
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 20120131140933
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 4
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: FILENAME=2706-2710-20120131140933-1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: FILENAME
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2706-2710-20120131140933-1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 5
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: MixMonitor
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: "/var/spool/asterisk/monitor/2706-2710-20120131140933-1328036973.683.wav"
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MIXMONITOR_FILENAME
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: /var/spool/asterisk/monitor/2706-2710-20120131140933-1328036973.683.wav
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 6
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Macro
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: stdexten,2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_EXTEN
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_CONTEXT
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_PRIORITY
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 6
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: ARG1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: macro-stdexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: s
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: temp=
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: temp
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: macro-stdexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: s
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 2
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: GotoIf
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: ?cfim:nocfim
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: macro-stdexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: s
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 9
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: MacroExit
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: 
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 0
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 7
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: CalendarStart=1328036973
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: CalendarStart
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1328036973
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 8
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: x=2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: x
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 9
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Macro
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: stdexten,2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_EXTEN
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_CONTEXT
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: internal
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_PRIORITY
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 9
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: ARG1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2710
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: context DATA: macro-stdexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: extension DATA: s
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 1
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: temp=
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:32 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:32 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: temp
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: macro-stdexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: s
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: GotoIf
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: ?cfim:nocfim
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: macro-stdexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: s
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 9
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: MacroExit
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 0
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2710
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 10
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: Dial
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: SIP/2710&SIP/2710s,15,tTwW
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALSTATUS
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNUMBER
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNAME
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: ANSWEREDTIME
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDTIME
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newchannel
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2710-00000185
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 0
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Down
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: accountcode DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.685
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1328036973.685"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Down"; ev.m_channel="SIP/2710-00000185"; m_pxCstaProvider->OnNewChannelEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1328036973.685 and callid =42
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.685}.callerID=, callerIdName=
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.685}.channel=SIP/2710-00000185, address=2710
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   state = DOWN => do nothing
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2710-00000185
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: SIPCALLID
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 0b556dd016d6293f57808b63710ab796@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.685
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ChannelUpdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2710-00000185
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.685
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channeltype DATA: SIP
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipcallid DATA: 0b556dd016d6293f57808b63710ab796@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipfullcontact DATA: sip:2710@10.0.1.114
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => channelupdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ChannelUpdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2710-00000185
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channeltype DATA: SIP
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipcallid DATA: 0b556dd016d6293f57808b63710ab796@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipfullcontact DATA: sip:2710@10.0.1.114
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: peername DATA: 2710
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => channelupdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2710-00000185
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNUMBER
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2710
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.685
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: NewCallerid
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2710-00000185
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2710
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.685
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: cid-callingpres DATA: 0 (Presentation Allowed, Not Screened)
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1328036973.685"; ev.m_callerId="2710"; ev.m_callerIdName="Andy rudd      #Id=39"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.685}. to new callerId 2710
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.685}.42 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.685}. to new calleridname Andy rudd      
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ExtensionStatus
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 2710
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: subscribehints
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: hint DATA: SIP/2710&SIP/2710s&IAX/2710i
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: status DATA: 8
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => extensionstatus
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Dial
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: subevent DATA: Begin
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: destination DATA: SIP/2710-00000185
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: destuniqueid DATA: 1328036973.685
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: dialstring DATA: 2710
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnDialEvent:CFT: ev.m_srcUniqueId="1328036973.683"; ev.m_destUniqueId="1328036973.685"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_callerId="2706"; m_pxCstaProvider->OnDialEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   linked calls {1328036973.683} <- {1328036973.685}
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.683}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.685}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] overriding {1328036973.683}. to new callerid 2706
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2710-00000185
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 5
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Ringing
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2710
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.685
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.685"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Ringing"; ev.m_channel="SIP/2710-00000185"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.685}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.685}.callerID=2710, callerIdName=Andy rudd      
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.685} ConnectedLineNum=2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.685} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1328036973.685}.address=2710
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1328036973.685, address=2710
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xb9a5650)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9a5650)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] GetCIDInfoFromSourceCall(1328036973.685)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   ConnectedLineNum/Name found in current AsteriskCall.
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   Exiting with cid/cidname/userData=2706/Andy rudd      #Id=39/
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ================================================================= start callmap dump...
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] DUMP OF ASTERISK CALLS MAP: {UNIQUEID} => call info:
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.683}.2706 callID=39 state=Up chann=Local/2706@internal-4305;1 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source= userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.684}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;2 CID= CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.685}.2710 callID=39 state=Ringing chann=SIP/2710-00000185 CID=2710 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] DUMP OF MONITOR CALLS MAP: {CALL_ID} => DEVICE: => STATE
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]     [39] => 2706 => INITIALIZED
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ================================================================= end callmap dump...
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] AddConnectionToCallModel {39, 2710} => ALERTING
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]  done, now CALL map has 1 items
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding calledNumber from 2710 => 2710
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   source call is {1328036973.683} and lastRedirection=[]
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 39
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   num_monitors = 1
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]     sending event:CFTE:ALERTING to xref=7, address=2710, callid=39, lastRedirection=, userData=
01/31/12 14:09:33 [6308] TRACE [TAPIProvider] OnAlerting xref=7 callId=39, alertingDevice=2710, callerId=2706, callerIdName=Andy rudd      #Id=39, calledID=2710 userData= cause=0
01/31/12 14:09:33 [6308] TRACE [TAPIProvider]  searching a TapiCall with callId 39 in tapiLine 0xba39b30
01/31/12 14:09:33 [6308] TRACE [TAPIProvider]   pTapiCall found with callId 39 and htCall 0x10099
01/31/12 14:09:33 [6308] TRACE [TAPIProvider]   alertingDevice callerid = 2706 
01/31/12 14:09:33 [6308] TRACE [TAPIProvider]     htapiline=0x100bb, deviceID=2706, htapicall=0x10099, callerid=2706, callerIdName=Andy rudd      #Id=39, calleddevice=2710, lastRedirection= userData=
01/31/12 14:09:33 [6308] TRACE [TAPIProvider]   LINECALLSTATE_RINGBACK htapicall=0x10099
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: Ringing
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 5
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Ringing
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.683"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Ringing"; ev.m_channel="Local/2706@internal-4305;1"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.683}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683}.callerID=2706, callerIdName=Andy rudd      
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683} ConnectedLineNum=2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1328036973.683}.address=2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1328036973.683, address=2706
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xb9a5e10)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9a5e10)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 3
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: CALLTIME=20120131140933
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: CALLTIME
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 20120131140933
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 4
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: FILENAME=2706-2706-20120131140933-1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: FILENAME
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2706-2706-20120131140933-1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 5
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: MixMonitor
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: "/var/spool/asterisk/monitor/2706-2706-20120131140933-1328036973.684.wav"
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MIXMONITOR_FILENAME
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: /var/spool/asterisk/monitor/2706-2706-20120131140933-1328036973.684.wav
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 6
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: Macro
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: stdexten,2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_EXTEN
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_CONTEXT
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_PRIORITY
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 6
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: ARG1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: macro-stdexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: s
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: temp=
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: temp
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: macro-stdexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: s
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: GotoIf
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: ?cfim:nocfim
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: macro-stdexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: s
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 9
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: MacroExit
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: MACRO_DEPTH
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 0
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 7
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: CalendarStart=1328036973
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: CalendarStart
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 1328036973
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 8
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: Set
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: x=2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: x
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 9
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: GotoIf
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: 0?cell,5706,1
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: extension DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: priority DATA: 10
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: application DATA: Dial
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: appdata DATA: SIP/2706&SIP/2706s&SIP/4706,20,tTwW
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newexten
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALSTATUS
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNUMBER
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNAME
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: ANSWEREDTIME
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDTIME
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newchannel
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 0
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Down
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: accountcode DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1328036973.686"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Down"; ev.m_channel="SIP/2706-00000186"; m_pxCstaProvider->OnNewChannelEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1328036973.686 and callid =43
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.686}.callerID=, callerIdName=
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.686}.channel=SIP/2706-00000186, address=2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   state = DOWN => do nothing
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: SIPCALLID
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 261d062251fc4e2d03a88f5c30adb7f1@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ChannelUpdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channeltype DATA: SIP
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipcallid DATA: 261d062251fc4e2d03a88f5c30adb7f1@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipfullcontact DATA: sip:2706@10.0.1.191:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => channelupdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ChannelUpdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channeltype DATA: SIP
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipcallid DATA: 261d062251fc4e2d03a88f5c30adb7f1@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipfullcontact DATA: sip:2706@10.0.1.191:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: peername DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => channelupdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNUMBER
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: NewCallerid
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: cid-callingpres DATA: 0 (Presentation Allowed, Not Screened)
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1328036973.686"; ev.m_callerId="2706"; ev.m_callerIdName="Andy rudd      #Id=39"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.686}. to new callerId 2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.686}.43 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.686}. to new calleridname Andy rudd      
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Dial
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: subevent DATA: Begin
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: destination DATA: SIP/2706-00000186
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: destuniqueid DATA: 1328036973.686
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: dialstring DATA: 2706
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnDialEvent:CFT: ev.m_srcUniqueId="1328036973.684"; ev.m_destUniqueId="1328036973.686"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_callerId="2706"; m_pxCstaProvider->OnDialEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   linked calls {1328036973.684} <- {1328036973.686}
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.684}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.686}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] overriding {1328036973.684}. to new callerid 2706
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newchannel
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706s-00000187
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 0
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Down
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: accountcode DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.687
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1328036973.687"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Down"; ev.m_channel="SIP/2706s-00000187"; m_pxCstaProvider->OnNewChannelEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1328036973.687 and callid =44
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.687}.callerID=, callerIdName=
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.687}.channel=SIP/2706s-00000187, address=2706s
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   state = DOWN => do nothing
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706s-00000187
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: SIPCALLID
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 41534fe224a2a66c25378fc42b2cc19d@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.687
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ChannelUpdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706s-00000187
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.687
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channeltype DATA: SIP
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipcallid DATA: 41534fe224a2a66c25378fc42b2cc19d@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipfullcontact DATA: sip:2706s@10.0.1.126:1644;rinstance=75feb83f7c8f79bc
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => channelupdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ChannelUpdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706s-00000187
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channeltype DATA: SIP
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipcallid DATA: 41534fe224a2a66c25378fc42b2cc19d@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipfullcontact DATA: sip:2706s@10.0.1.126:1644;rinstance=75feb83f7c8f79bc
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: peername DATA: 2706s
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => channelupdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706s-00000187
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNUMBER
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2706s
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.687
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: NewCallerid
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706s-00000187
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.687
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: cid-callingpres DATA: 0 (Presentation Allowed, Not Screened)
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1328036973.687"; ev.m_callerId="2706"; ev.m_callerIdName="Andy rudd      #Id=39"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.687}. to new callerId 2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.687}.44 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.687}. to new calleridname Andy rudd      
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Dial
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: subevent DATA: Begin
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: destination DATA: SIP/2706s-00000187
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: destuniqueid DATA: 1328036973.687
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: dialstring DATA: 2706s
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnDialEvent:CFT: ev.m_srcUniqueId="1328036973.684"; ev.m_destUniqueId="1328036973.687"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_callerId="2706"; m_pxCstaProvider->OnDialEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   linked calls {1328036973.684} <- {1328036973.687}
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.684}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.687}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] overriding {1328036973.684}. to new callerid 2706
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newchannel
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/4706-00000188
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 0
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Down
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: accountcode DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: internal
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.688
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newchannel
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewChannelEvent:CFT: ev.m_uniqueId="1328036973.688"; ev.m_callerId=""; ev.m_callerIdName=""; ev.m_state="Down"; ev.m_channel="SIP/4706-00000188"; m_pxCstaProvider->OnNewChannelEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] Create AsteriskCall with uniqueId = 1328036973.688 and callid =45
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.688}.callerID=, callerIdName=
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.688}.channel=SIP/4706-00000188, address=4706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   state = DOWN => do nothing
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/4706-00000188
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: SIPCALLID
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2cd6e51c59a596746745593331523cb2@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.688
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ChannelUpdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/4706-00000188
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.688
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channeltype DATA: SIP
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipcallid DATA: 2cd6e51c59a596746745593331523cb2@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipfullcontact DATA: sip:4706@192.168.2.43:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => channelupdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ChannelUpdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/4706-00000188
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channeltype DATA: SIP
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipcallid DATA: 2cd6e51c59a596746745593331523cb2@10.0.0.141:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: sipfullcontact DATA: sip:4706@192.168.2.43:5060
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: peername DATA: 4706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => channelupdate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/4706-00000188
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNUMBER
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: value DATA: 4706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.688
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: NewCallerid
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/4706-00000188
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.688
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: cid-callingpres DATA: 0 (Presentation Allowed, Not Screened)
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newcallerid
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewCallerIdEvent:CFT: ev.m_uniqueId="1328036973.688"; ev.m_callerId="2706"; ev.m_callerIdName="Andy rudd      #Id=39"; m_pxCstaProvider->OnNewCallerIdEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.688}. to new callerId 2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.688}.45 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.688}. to new calleridname Andy rudd      
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Dial
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: subevent DATA: Begin
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: destination DATA: SIP/4706-00000188
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: destuniqueid DATA: 1328036973.688
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: dialstring DATA: 4706
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => dial
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnDialEvent:CFT: ev.m_srcUniqueId="1328036973.684"; ev.m_destUniqueId="1328036973.688"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_callerId="2706"; m_pxCstaProvider->OnDialEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   linked calls {1328036973.684} <- {1328036973.688}
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.684}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.688}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] overriding {1328036973.684}. to new callerid 2706
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: ExtensionStatus
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: context DATA: subscribehints
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: hint DATA: SIP/2706&SIP/2706s
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: status DATA: 8
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => extensionstatus
01/31/12 14:09:33 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 5
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Ringing
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.686"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Ringing"; ev.m_channel="SIP/2706-00000186"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.686}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.686}.callerID=2706, callerIdName=Andy rudd      
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.686} ConnectedLineNum=2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.686} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1328036973.686}.address=2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1328036973.686, address=2706
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xb9a5830)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9a5830)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] GetCIDInfoFromSourceCall(1328036973.686)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   ConnectedLineNum/Name found in current AsteriskCall.
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   Exiting with cid/cidname/userData=2706/Andy rudd      #Id=39/
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ================================================================= start callmap dump...
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] DUMP OF ASTERISK CALLS MAP: {UNIQUEID} => call info:
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.683}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;1 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source= userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.684}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;2 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.685}.2710 callID=39 state=Ringing chann=SIP/2710-00000185 CID=2710 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.686}.2706 callID=39 state=Ringing chann=SIP/2706-00000186 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.687}.2706s callID=39 state=Down chann=SIP/2706s-00000187 CID=2706 CIDName=Andy rudd       ConLineNum= ConLineName= lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.688}.4706 callID=39 state=Down chann=SIP/4706-00000188 CID=2706 CIDName=Andy rudd       ConLineNum= ConLineName= lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] DUMP OF MONITOR CALLS MAP: {CALL_ID} => DEVICE: => STATE
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]     [39] => 2706 => INITIALIZED
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]     [39] => 2710 => ALERTING
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ================================================================= end callmap dump...
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] AddConnectionToCallModel {39, 2706} => ALERTING
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]  done, now CALL map has 1 items
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   event minimization RULE-4: (callerid = 2706) == (called = 2706) == (address = 2706)
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/4706-00000188
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 5
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Ringing
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.688
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.688"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Ringing"; ev.m_channel="SIP/4706-00000188"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.688}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.688}.callerID=2706, callerIdName=Andy rudd      
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.688} ConnectedLineNum=2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.688} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1328036973.688}.address=4706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1328036973.688, address=4706
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xb9be940)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9be940)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] GetCIDInfoFromSourceCall(1328036973.688)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   ConnectedLineNum/Name found in current AsteriskCall.
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   Exiting with cid/cidname/userData=2706/Andy rudd      #Id=39/
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ================================================================= start callmap dump...
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] DUMP OF ASTERISK CALLS MAP: {UNIQUEID} => call info:
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.683}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;1 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source= userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.684}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;2 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.685}.2710 callID=39 state=Ringing chann=SIP/2710-00000185 CID=2710 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.686}.2706 callID=39 state=Ringing chann=SIP/2706-00000186 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.687}.2706s callID=39 state=Down chann=SIP/2706s-00000187 CID=2706 CIDName=Andy rudd       ConLineNum= ConLineName= lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.688}.4706 callID=39 state=Ringing chann=SIP/4706-00000188 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] DUMP OF MONITOR CALLS MAP: {CALL_ID} => DEVICE: => STATE
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]     [39] => 2706 => ALERTING
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]     [39] => 2710 => ALERTING
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ================================================================= end callmap dump...
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] AddConnectionToCallModel {39, 4706} => ALERTING
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]  done, now CALL map has 1 items
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   event minimization RULE-4: (callerid = 2706) == (called = 2706) == (address = 4706)
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706s-00000187
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 5
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Ringing
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.687
01/31/12 14:09:33 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.687"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Ringing"; ev.m_channel="SIP/2706s-00000187"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   overriding {1328036973.687}.39 to new callId 39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.687}.callerID=2706, callerIdName=Andy rudd      
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.687} ConnectedLineNum=2706
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   setting {1328036973.687} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   state = RINGING => Send ALERTING to {1328036973.687}.address=2706s
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionAlerting uniqueId=1328036973.687, address=2706s
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xb9be760)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9be760)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] GetCIDInfoFromSourceCall(1328036973.687)
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   ConnectedLineNum/Name found in current AsteriskCall.
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]   Exiting with cid/cidname/userData=2706/Andy rudd      #Id=39/
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ================================================================= start callmap dump...
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] DUMP OF ASTERISK CALLS MAP: {UNIQUEID} => call info:
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.683}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;1 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source= userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.684}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;2 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.685}.2710 callID=39 state=Ringing chann=SIP/2710-00000185 CID=2710 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.686}.2706 callID=39 state=Ringing chann=SIP/2706-00000186 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.687}.2706s callID=39 state=Ringing chann=SIP/2706s-00000187 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]   {1328036973.688}.4706 callID=39 state=Ringing chann=SIP/4706-00000188 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] DUMP OF MONITOR CALLS MAP: {CALL_ID} => DEVICE: => STATE
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]     [39] => 2706 => ALERTING
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]     [39] => 4706 => ALERTING
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap]     [39] => 2710 => ALERTING
01/31/12 14:09:33 [6308] TRACE0[ASTCallMap] ================================================================= end callmap dump...
01/31/12 14:09:33 [6308] TRACE [ASTCallMap] AddConnectionToCallModel {39, 2706s} => ALERTING
01/31/12 14:09:33 [6308] TRACE [ASTCallMap]  done, now CALL map has 1 items
01/31/12 14:09:33 [6308] TRACE [ASTCstaProvider]   event minimization RULE-4: (callerid = 2706) == (called = 2706) == (address = 2706s)
01/31/12 14:09:33 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: ChannelUpdate
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: system,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channeltype DATA: SIP
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: sipcallid DATA: 261d062251fc4e2d03a88f5c30adb7f1@10.0.0.141:5060
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: sipfullcontact DATA: sip:2706@10.0.1.191:5060
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: peername DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => channelupdate
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 6
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Up
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:34 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.686"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Up"; ev.m_channel="SIP/2706-00000186"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   setting {1328036973.686}.callerID=2706, callerIdName=Andy rudd      
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   setting {1328036973.686} ConnectedLineNum=2706
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   setting {1328036973.686} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1328036973.686}.address=2706
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1328036973.686, address=2706
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xb9a5830)
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] GetCIDInfoFromSourceCall(1328036973.686)
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]   ConnectedLineNum/Name found in current AsteriskCall.
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]   Exiting with cid/cidname/userData=2706/Andy rudd      #Id=39/
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ================================================================= start callmap dump...
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] DUMP OF ASTERISK CALLS MAP: {UNIQUEID} => call info:
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.683}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;1 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source= userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.684}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;2 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.685}.2710 callID=39 state=Ringing chann=SIP/2710-00000185 CID=2710 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.686}.2706 callID=39 state=Up chann=SIP/2706-00000186 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.687}.2706s callID=39 state=Ringing chann=SIP/2706s-00000187 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.688}.4706 callID=39 state=Ringing chann=SIP/4706-00000188 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] DUMP OF MONITOR CALLS MAP: {CALL_ID} => DEVICE: => STATE
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 2706 => ALERTING
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 4706 => ALERTING
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 2710 => ALERTING
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 2706s => ALERTING
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ================================================================= end callmap dump...
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] AddConnectionToCallModel {39, 2706} => CONNECTED
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]  done, now CALL map has 1 items
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   event minimization RULE-4: (callerid = 2706) == (called = 2706) == (address = 2706)
01/31/12 14:09:34 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALSTATUS
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: ANSWER
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: Hangup
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/4706-00000188
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.688
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: cause DATA: 26
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: cause-txt DATA: Unknown
01/31/12 14:09:34 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1328036973.688"; ev.m_cause="26"; m_pxCstaProvider->OnHangupEvent(ev);
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9be940)
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] GetStateOfDevice {39, 2706}
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]    deviceState = CONNECTED
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]  callMap.size == 6
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   handleConnectionDisconnected {1328036973.688} to 4706
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0xb9be940)
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1328036973.688, logicaddress=4706, cause=-1
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9be940)
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ================================================================= start callmap dump...
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] DUMP OF ASTERISK CALLS MAP: {UNIQUEID} => call info:
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.683}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;1 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source= userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.684}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;2 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.685}.2710 callID=39 state=Ringing chann=SIP/2710-00000185 CID=2710 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.686}.2706 callID=39 state=Up chann=SIP/2706-00000186 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.687}.2706s callID=39 state=Ringing chann=SIP/2706s-00000187 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.688}.4706 callID=39 state=Ringing chann=SIP/4706-00000188 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=-1
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] DUMP OF MONITOR CALLS MAP: {CALL_ID} => DEVICE: => STATE
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 2706 => CONNECTED
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 4706 => ALERTING
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 2710 => ALERTING
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 2706s => ALERTING
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ================================================================= end callmap dump...
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 39
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]   num_monitors = 1
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]     sending event:CFTE:CONNCLEARED to xref=7, address=2706, callid=39
01/31/12 14:09:34 [6308] TRACE [TAPIProvider] OnConnectionCleared xref=7 callId=39, releasingDevice=4706 cause=-1
01/31/12 14:09:34 [6308] TRACE [TAPIProvider]  searching a TapiCall with callId 39 in tapiLine 0xba39b30
01/31/12 14:09:34 [6308] TRACE [TAPIProvider]     htapiline=0x100bb, deviceID=2706, htapicall=0x10099, releasingDevice=4706, callerid=N/A, callerIdName=N/A, calleddevice=N/A, lastRedirection=N/A
01/31/12 14:09:34 [6308] TRACE [TAPIProvider]   LINEDISCONNECTMODE_UNKNOWN htapicall=0x10099
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] RemoveConnection {39}=> 4706
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   removed uniqueId=1328036973.688 call from MAP
01/31/12 14:09:34 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: Hangup
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706s-00000187
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.687
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:34 [6664] TRACE [TAPIProvider] TSPI_lineDrop() hdCall=0xb9a47d0
01/31/12 14:09:34 [6664] TRACE [TAPIProvider]   got TapiCall=0xb9a47d0
01/31/12 14:09:34 [6664] TRACE0[TAPIProvider] ================================================================= start callmap dump...
01/31/12 14:09:34 [6664] TRACE0[TAPIProvider] DUMP OF TSP CALLS MAP: [HDRVCALL] => call info:
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6664] TRACE0[TAPIProvider]   [0xb9a47d0] TapiLine=0x000000000BA39B30 hdrivercall=0x000000000B9A47D0 htapicall=0x0000000000010099 callID=39 address=2706 CID=2706 CIDName=Andy rudd      #Id=39 lastRedir=4706 called=2710 userData= isPredictive=0 cause=-1
01/31/12 14:09:34 [6664] TRACE0[TAPIProvider] DUMP OF CALL-ID MAP: {CALL_ID} => hdrivercall
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:34 [6664] TRACE0[TAPIProvider]       [39] => TapiLine=0x000000000BA39B30 hdrivercall=0x000000000B9A47D0 htapicall=0x0000000000010099 callID=39 address=2706 CID=2706 CIDName=Andy rudd      #Id=39 lastRedir=4706 called=2710 userData= isPredictive=0 cause=-1
01/31/12 14:09:34 [6664] TRACE0[TAPIProvider] ================================================================= end callmap dump...
01/31/12 14:09:34 [6664] TRACE [TAPIProvider]   got callID=39
01/31/12 14:09:34 [6664] TRACE [ASTCstaProvider] ASTCstaProvider::ClearConnection callID=39 address=2706
01/31/12 14:09:34 [6664] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9a5e10)
01/31/12 14:09:34 [6664] TRACE [ASTCstaProvider]   Hangup callid=39,channel=Local/2706@internal-4305;1
01/31/12 14:09:34 [6664] TRACE [ASTProvider] ASTProvider::Hangup channel=Local/2706@internal-4305;1
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6664] TRACE [ASTProvider] ASTProvider::SendCommand => 
Action: Hangup
Channel: Local/2706@internal-4305;1
ActionID: 22
Async: 1
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: cause DATA: 26
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: cause-txt DATA: Unknown
01/31/12 14:09:34 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1328036973.687"; ev.m_cause="26"; m_pxCstaProvider->OnHangupEvent(ev);
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9be760)
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] GetStateOfDevice {39, 2706}
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]    deviceState = CONNECTED
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]  callMap.size == 5
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   handleConnectionDisconnected {1328036973.687} to 2706s
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0xb9be760)
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1328036973.687, logicaddress=2706s, cause=-1
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9be760)
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ================================================================= start callmap dump...
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] DUMP OF ASTERISK CALLS MAP: {UNIQUEID} => call info:
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.683}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;1 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source= userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.684}.2706 callID=39 state=Ringing chann=Local/2706@internal-4305;2 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.685}.2710 callID=39 state=Ringing chann=SIP/2710-00000185 CID=2710 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.686}.2706 callID=39 state=Up chann=SIP/2706-00000186 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.687}.2706s callID=39 state=Ringing chann=SIP/2706s-00000187 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.684 userData= cause=-1
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] DUMP OF MONITOR CALLS MAP: {CALL_ID} => DEVICE: => STATE
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 2706 => CONNECTED
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 2710 => ALERTING
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]     [39] => 2706s => ALERTING
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ================================================================= end callmap dump...
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] GetMonitorSetFromCallModel = 39
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]   num_monitors = 1
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]     sending event:CFTE:CONNCLEARED to xref=7, address=2706, callid=39
01/31/12 14:09:34 [6308] TRACE [TAPIProvider] OnConnectionCleared xref=7 callId=39, releasingDevice=2706s cause=-1
01/31/12 14:09:34 [6308] TRACE [TAPIProvider]  searching a TapiCall with callId 39 in tapiLine 0xba39b30
01/31/12 14:09:34 [6308] TRACE [TAPIProvider]     htapiline=0x100bb, deviceID=2706, htapicall=0x10099, releasingDevice=2706s, callerid=N/A, callerIdName=N/A, calleddevice=N/A, lastRedirection=N/A
01/31/12 14:09:34 [6308] TRACE [TAPIProvider]   LINEDISCONNECTMODE_UNKNOWN htapicall=0x10099
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] RemoveConnection {39}=> 2706s
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   removed uniqueId=1328036973.687 call from MAP
01/31/12 14:09:34 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNAME
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: DIALEDPEERNUMBER
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: BRIDGEPEER
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: BRIDGEPEER
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 6
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Up
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.684"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Up"; ev.m_channel="Local/2706@internal-4305;2"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684}.callerID=2706, callerIdName=Andy rudd      
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684} ConnectedLineNum=2706
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   setting {1328036973.684} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1328036973.684}.address=2706
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1328036973.684, address=2706
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xba38e00)
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
01/31/12 14:09:34 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: NewAccountCode
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: accountcode DATA: 
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: oldaccountcode DATA: 
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => newaccountcode
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: Bridge
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: bridgestate DATA: Link
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: bridgetype DATA: core
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel1 DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel2 DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid1 DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid2 DATA: 1328036973.686
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: callerid1 DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: callerid2 DATA: 2706
01/31/12 14:09:34 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => bridge
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] OnLinkEvent:CFT: ev.m_srcUniqueId="1328036973.684"; ev.m_destUniqueId="1328036973.686"; m_pxCstaProvider->OnLinkEvent(ev);
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   set {1328036973.686}.lastRedirectionDevice=
01/31/12 14:09:34 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: BRIDGEPEER
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: BRIDGEPVTCALLID
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: 261d062251fc4e2d03a88f5c30adb7f1@10.0.0.141:5060
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: BRIDGEPEER
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: BRIDGEPEER
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: BRIDGEPVTCALLID
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: 261d062251fc4e2d03a88f5c30adb7f1@10.0.0.141:5060
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.684
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: VarSet
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: dialplan,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2706-00000186
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: variable DATA: BRIDGEPEER
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: value DATA: Local/2706@internal-4305;2
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.686
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => varset
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: Newstate
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: Local/2706@internal-4305;1
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channelstate DATA: 6
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channelstatedesc DATA: Up
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.683
01/31/12 14:09:34 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => newstate
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] OnNewStateEvent:CFT: ev.m_uniqueId="1328036973.683"; ev.m_callerIdName="Andy rudd      #Id=39"; ev.m_state="Up"; ev.m_channel="Local/2706@internal-4305;1"; m_pxCstaProvider->OnNewStateEvent(ev);
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call containsCallId(39)
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call is NOT predictive
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683}.callerID=2706, callerIdName=Andy rudd      
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683} ConnectedLineNum=2706
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   setting {1328036973.683} ConnectedLineName=Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] Call does not contains UserData
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   state = UP => Send ESTABLISHED to {1328036973.683}.address=2706
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionConnected uniqueId=1328036973.683, address=2706
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] ASTCallMap::GetSourceCall(0xb9a5e10)
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]   SourceCall is 1328036973.683
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   event minimization RULE-9: Do not send EVENTS to local channels
01/31/12 14:09:34 [6308] TRACE [ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: ExtensionStatus
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: exten DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: context DATA: subscribehints
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: hint DATA: SIP/2706&SIP/2706s
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: status DATA: 1
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] ASTProvider::HandleEvent => extensionstatus
01/31/12 14:09:34 [6308] TRACE0[ASTProvider]  <== asterisk protocol event _______________________________
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: response DATA: Success
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: actionid DATA: 22
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: message DATA: Channel Hungup
01/31/12 14:09:34 [6308] TRACE [ASTProvider]  <== asterisk protocol response__________________________
01/31/12 14:09:34 [6664] TRACE [ASTProvider]   return = ok
01/31/12 14:09:34 [6664] TRACE [TAPIProvider]   ClearConnection() returned ok. Sending LINECALLSTATE_IDLE  htapicall=0x10099
01/31/12 14:09:34 [7888] TRACE [TAPIProvider] TSPI_lineDrop() hdCall=0xb9a47d0
01/31/12 14:09:34 [7888] TRACE [TAPIProvider]   got TapiCall=0xb9a47d0
01/31/12 14:09:34 [7888] TRACE0[TAPIProvider] ================================================================= start callmap dump...
01/31/12 14:09:34 [7888] TRACE0[TAPIProvider] DUMP OF TSP CALLS MAP: [HDRVCALL] => call info:
01/31/12 14:09:34 [7888] TRACE0[TAPIProvider]   [0xb9a47d0] TapiLine=0x000000000BA39B30 hdrivercall=0x000000000B9A47D0 htapicall=0x0000000000010099 callID=39 address=2706state= CID=2706 CIDName=Andy rudd      #Id=39 lastRedir=2706s called=2710 userData= isPredictive=0 cause=-1
01/31/12 14:09:34 [7888] TRACE0[TAPIProvider] DUMP OF CALL-ID MAP: {CALL_ID} => hdrivercall
01/31/12 14:09:34 [7888] TRACE0[TAPIProvider]       [39] => TapiLine=0x000000000BA39B30 hdrivercall=0x000000000B9A47D0 htapicall=0x0000000000010099 callID=39 address=2706state= CID=2706 CIDName=Andy rudd      #Id=39 lastRedir=2706s called=2710 userData= isPredictive=0 cause=-1
01/31/12 14:09:34 [7888] TRACE0[TAPIProvider] ================================================================= end callmap dump...
01/31/12 14:09:34 [7888] TRACE [TAPIProvider]   got callID=39
01/31/12 14:09:34 [7888] TRACE [ASTCstaProvider] ASTCstaProvider::ClearConnection callID=39 address=2706
01/31/12 14:09:34 [7888] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9a5e10)
01/31/12 14:09:34 [7888] TRACE [ASTCstaProvider]   Hangup callid=39,channel=Local/2706@internal-4305;1
01/31/12 14:09:34 [7888] TRACE [ASTProvider] ASTProvider::Hangup channel=Local/2706@internal-4305;1
01/31/12 14:09:34 [7888] TRACE [ASTProvider] ASTProvider::SendCommand => 
Action: Hangup
Channel: Local/2706@internal-4305;1
ActionID: 23
Async: 1
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: event DATA: Hangup
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: privilege DATA: call,all
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: channel DATA: SIP/2710-00000185
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: uniqueid DATA: 1328036973.685
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridnum DATA: 2710
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: calleridname DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinenum DATA: 2706
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: connectedlinename DATA: Andy rudd      #Id=39
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: cause DATA: 16
01/31/12 14:09:34 [6308] TRACE0[ASTProvider] HEADER: cause-txt DATA: Normal Clearing
01/31/12 14:09:34 [6308] TRACE [ASTProvider] ASTProvider::HandleEvent => hangup
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] OnHangup:CFT: ev.m_uniqueId="1328036973.685"; ev.m_cause="16"; m_pxCstaProvider->OnHangupEvent(ev);
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9a5650)
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] GetStateOfDevice {39, 2706}
01/31/12 14:09:34 [6308] TRACE [ASTCallMap]    deviceState = CONNECTED
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]  callMap.size == 4
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider]   handleConnectionDisconnected {1328036973.685} to 2710
01/31/12 14:09:34 [6308] TRACE [ASTCallMap] ASTCallMap::GetLogicAddress(0xb9a5650)
01/31/12 14:09:34 [6308] TRACE [ASTCstaProvider] ASTCstaProvider::handleConnectionDisconnected uniqueId=1328036973.685, logicaddress=2710, cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ASTCallMap::GetLogicCallId(0xb9a5650)
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] ================================================================= start callmap dump...
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap] DUMP OF ASTERISK CALLS MAP: {UNIQUEID} => call info:
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.683}.2706 callID=39 state=Up chann=Local/2706@internal-4305;1 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source= userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.684}.2706 callID=39 state=Up chann=Local/2706@internal-4305;2 CID=2706 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0
01/31/12 14:09:34 [6308] TRACE0[ASTCallMap]   {1328036973.685}.2710 callID=39 state=Ringing chann=SIP/2710-00000185 CID=2710 CIDName=Andy rudd       ConLineNum=2706 ConLineName=Andy rudd      #Id=39 lastRedir= source=1328036973.683 userData= cause=0

[activatsp]

Hi!

Sorry but at this time ActivaTSP dosn't support dial multiple extensions.

Activa Team