Avaya IP Office SIP Trunking disconnects on outgoing calls only. Help Please.

RodneyMcSnow · Jun 26, 2014

Customer has an IPOffice 500V2 on Rel 9.0.3 firmware runiing sip trunks from Las Vegas to Chicago on an MPLS Circuit.

This has been an ongoing issue for the past few years that when a user calls out local, long distance or toll free they get disconnected within the first 15-30 seconds. I has been intermittent but Today has been almost every call.

This is a capture of what I am seeing: Anyone have any thoughts?

11:24:16 46992246mS PRN: Monitor Status IP 500 9.0.3.0 build 941
11:24:16 46992246mS PRN: LAW=U PRI=0, BRI=0, ALOG=4, VCOMP=64, MDM=0, WAN=0, MODU=2 LANM=0 CkSRC=0 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=1(TOT=229)
11:24:26 47002056mS CMExtnRx: v=6920, p1=0
CMReleaseComp
Line: type=DigitalExtn 6 Call: lid=0 id=1765 in=0
11:24:26 47002057mS CMCallEvt: 0.1765.0 229 Trish Zarlingo.0: StateChange: END=A CMCSRingBack->CMCSCompleted
11:24:26 47002058mS CMExtnEvt: v=21 State, new=PortRecoverDelay old=Alerting,0,0,Trish Zarlingo
11:24:26 47002059mS CMLOGGING: CALL:2014/06/2611:23,00:00:00,052,6920,O,17027553279@sip.emcor.net,97027553279,TrishZarlingo,,,0,,""n/a,0
11:24:26 47002059mS CD: CALL: 0.1765.0 BState=Ringing Cut=2 Music=0.0 Aend="TLine 17" (8.23) Bend="Line 17" [Line 17] (0.0) CalledNum=17027553279@sip.emcor.net () CallingNum=6920 (Trish Zarlingo) Internal=0 Time=62788 AState=Idle
11:24:26 47002059mS CD: CALL: 0.1765.0 Deleted
11:24:26 47002060mS CMExtnEvt: Trish Zarlingo: CALL LOST (CMCauseNormal)
11:24:26 47002060mS CMExtnEvt: Trish Zarlingo: Extn(6920) Calling Party Number(6920) Type(CMNTypeInternal)
11:24:26 47002060mS CMExtnEvt: Trish Zarlingo: CMExtnHandler::SetCurrent( id: 1765->0 )
11:24:26 47002060mS CMCallEvt: 0.1765.0 -1 Trish Zarlingo.-1: StateChange: END=X CMCSCompleted->CMCSDelete
11:24:26 47002062mS CMLineTx: v=0
CMReleaseComp
Line: type=SIPLine 17 Call: lid=17 id=1768 in=0
Cause=16, Normal call clearing
11:24:26 47002062mS Sip: 17.1768.0 -1 SIPTrunk Endpoint(f4d5d36c) received CMReleaseComp
11:24:26 47002064mS SIP Call Tx: 17
CANCEL sip:17027553279@sip.emcor.net SIP/2.0
Via: SIP/2.0/UDP 10.0.215.10:5060;rport;branch=z9hG4bK4a29c7ec73a45f75b4c70998717baf86
Route: <sip:rw-25853dac@10.85.9.21;lr>
Route: <sip:10.85.9.20:15060;transport=udp;ibmsid=local.1390390940471_8845039_8857652;lr;ibmdrr>
Route: <sip:10.85.9.20:15060;transport=tcp;ibmsid=local.1390390940471_8845039_8857652;lr;ibmdrr>
Route: <sip:rw-25853dac@10.85.9.21;lr;transport=TCP>
From: "Trish Zarlingo" <sip:6920@sip.emcor.net>;tag=945901f5851db0e5
To: <sip:17027553279@sip.emcor.net>
Call-ID: f0f63a53659d69dc2955f2bc4d22b053
CSeq: 1144393089 CANCEL
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
Supported: timer
Reason: Q.850;cause=16;text="Normal call clearing"
User-Agent: IP Office 9.0.3.0 build 941
Content-Length: 0

11:24:26 47002064mS SIP Tx: UDP 10.0.215.10:5060 -> 10.85.9.21:5060
CANCEL sip:17027553279@sip.emcor.net SIP/2.0
Via: SIP/2.0/UDP 10.0.215.10:5060;rport;branch=z9hG4bK4a29c7ec73a45f75b4c70998717baf86
Route: <sip:rw-25853dac@10.85.9.21;lr>
Route: <sip:10.85.9.20:15060;transport=udp;ibmsid=local.1390390940471_8845039_8857652;lr;ibmdrr>
Route: <sip:10.85.9.20:15060;transport=tcp;ibmsid=local.1390390940471_8845039_8857652;lr;ibmdrr>
Route: <sip:rw-25853dac@10.85.9.21;lr;transport=TCP>
From: "Trish Zarlingo" <sip:6920@sip.emcor.net>;tag=945901f5851db0e5
To: <sip:17027553279@sip.emcor.net>
Call-ID: f0f63a53659d69dc2955f2bc4d22b053
CSeq: 1144393089 CANCEL
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
Supported: timer
Reason: Q.850;cause=16;text="Normal call clearing"
User-Agent: IP Office 9.0.3.0 build 941
Content-Length: 0

11:24:26 47002065mS CMCallEvt: END CALL:229 (f4cc2c64)
11:24:26 47002066mS CMTARGET: 0.1765.0 -1 BaseEP: ~CMTargetHandler f4cd6f34 ep f4d60a0c
11:24:26 47002066mS CMCallEvt: 0.1765.0 -1 BaseEP: DELETE CMEndpoint f4d60a0c TOTAL NOW=1 CALL_LIST=0
11:24:26 47002067mS CMMap: a=8.23 b=0.0 PCGS CPReserveCodec (pcp[541]b0r1) true
11:24:26 47002067mS CMMap: PCG::UnmapBChan pcp[541]b0r1 cp_b f55fe014 other_cp_b f57eafc4
11:24:26 47002067mS CMMap: a=8.23 b=4.33 M02
11:24:26 47002067mS H323Evt: SetOperational 225 10.0.215.10:49154 to 0
11:24:26 47002068mS CMMap: PCG::UnmapBChan pcp[149]b1r0 cp_b f57eafc4 other_cp_b 0
11:24:26 47002068mS CMMap: PlatformConnectionAudioSAP:

isconnectVoice rtpRelay ID: 2 Close success
11:24:26 47002068mS CMMap: a=4.17 b=0.0 Mapper::FreeCodec freed CMRTVocoder resource busy 1, total 64
11:24:26 47002126mS RES: Thu 26/6/2014 11:24:25 FreeMem=52065756 51264548(3) CachedMem=801208 CMMsg=7(9) Buff=5200 1372 999 7433 4 Links=29351 BTree=13973 CPU=07.32% CPUStats=10/17/902/20056/21671/0/0 MCR=0 MCW=0
11:24:26 47002126mS RES2: IP 500 9.0.3.0 build 941 Tasks=45 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=84 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=64(TLS=2) TAPI=0 CF=UMNT
11:24:26 47002126mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)

SupportDude · Jun 26, 2014

Can you post another trace with the INVITE message?
On the monitor SIP tab enable;
SIP (verbose)
SIP Tx
SIP Rx

Post up the entire trace from beginning of call to the end.

-SD-

http://www.mysupportguy.net

RodneyMcSnow · Jun 26, 2014

Here is a copy of the log for the past hour

Contact: <sip:7026432211@10.85.9.10:5070;transport=tcp;gsid=b6292d50-fd5b-11e3-8bec-d89d677987ec>
From: "Don Mitchell" <sip:6928@sip.emcor.net>;tag=928f21eb7980ed6c
Call-ID: 22cc52491d7241c2f40b63fcc0e989cb
CSeq: 1354698919 INVITE
Via: SIP/2.0/UDP 10.0.215.10:5060;rport=5060;branch=z9hG4bK9bc60315fbf7fa89ccaedd426cfa6698
Content-Type: application/sdp
Content-Length: 242

v=0
o=BroadWorks 815443641 815426061 IN IP4 10.85.9.10
s=-
c=IN IP4 10.85.9.10
t=0 0
m=audio 6420 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=maxptime:20
11:00:11 45547345mS SIP Call Rx: 17
SIP/2.0 180 Ringing
To: <sip:17026432211@sip.emcor.net>;tag=1c807058413
P-Asserted-Identity: <sip:7026432211@sip.emcor.net>
P-Location: SM;origlocname="Hansen";origsiglocname="Hansen";origmedialocname="Hansen";termlocname="Ashburn";termsiglocname="Ashburn";termmedialocname="Ashburn";smaccounting="true"
P-AV-Message-Id: 6_2
Server: Audiocodes-Sip-Gateway-Mediant 1000 - MSBG/v.6.00AL.022.004 AVAYA-SM-6.3.4.0.634014
Av-Global-Session-ID: b6292d50-fd5b-11e3-8bec-d89d677987ec
Content-Disposition: session;handling=required
Remote-Party-ID: <sip:7026432211@8.13.222.209;user=phone>;screen=yes;party=called;privacy=off;id-type=subscriber
Allow: ACK, BYE, CANCEL, INFO, INVITE, OPTIONS, PRACK, REFER, NOTIFY, UPDATE
Record-Route: <sip:rw-25853dac@10.85.9.21;lr;transport=TCP>
Record-Route: <sip:10.85.9.20:15060;transport=tcp;ibmsid=local.1390390940471_8843986_8856599;lr;ibmdrr>
Record-Route: <sip:10.85.9.20:15060;transport=udp;ibmsid=local.1390390940471_8843986_8856599;lr;ibmdrr>
Record-Route: <sip:rw-25853dac@10.85.9.21;lr>
Contact: <sip:7026432211@10.85.9.10:5070;transport=tcp;gsid=b6292d50-fd5b-11e3-8bec-d89d677987ec>
From: "Don Mitchell" <sip:6928@sip.emcor.net>;tag=928f21eb7980ed6c
Call-ID: 22cc52491d7241c2f40b63fcc0e989cb
CSeq: 1354698919 INVITE
Via: SIP/2.0/UDP 10.0.215.10:5060;rport=5060;branch=z9hG4bK9bc60315fbf7fa89ccaedd426cfa6698
Content-Type: application/sdp
Content-Length: 242

v=0
o=BroadWorks 815443641 815426061 IN IP4 10.85.9.10
s=-
c=IN IP4 10.85.9.10
t=0 0
m=audio 6420 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=maxptime:20
11:00:11 45547347mS Sip: 17.1683.0 202 SIPTrunk Endpoint(f4c41d84) SetRfc2833TxPayload: use RFC2833 for dtmf
11:00:11 45547347mS Sip: 17.1683.0 202 SIPTrunk Endpoint(f4c41d84) SetRemoteRTPAddress to 10.85.9.10:6420
11:00:11 45547348mS CMLineRx: v=0
CMAlerting
Line: type=SIPLine 17 Call: lid=17 id=1683 in=0
Called[Don Mitchell] Type=Default (100) Reason=CMDRdirect Calling[6928] Type=Internal Plan=Default
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=97026432211
IE CMIEDeviceDetail (231) LOCALE=enu HW=14 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x1 rx_gain=32 tx_gain=32 ep_callid=1683 ipaddr=10.0.215.10 apps=0 loc=999 em_loc=999 features2=0x0
11:00:11 45547348mS CMARS: LINE ep Received: CMAlerting - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
11:00:11 45547348mS CMARS: LINE IS NOW THE B END OF THE CALL - CMARSEndpoint::RequestEnd()
11:00:11 45547348mS CMARS: CMARSEndpoint::CallLost(cause=124) - Address: 0.1682.0 202 ARS for SIP MAIN - Call State: CMCSOverlapRecv
11:00:11 45547348mS CMCallEvt: 0.1682.0 -1 ARS for SIP MAIN: StateChange: END=X CMCSOverlapRecv->CMCSDelete
11:00:11 45547349mS CMCallEvt: 17.1683.0 202 SIPTrunk Endpoint: StateChange: END=B CMCSOffering->CMCSRinging
11:00:11 45547350mS CMCallEvt: 261.1680.0 202 Don Mitchell.0: StateChange: END=A CMCSDialling->CMCSRingBack
11:00:11 45547351mS CMExtnEvt: v=9 State, new=Alerting old=Dialling,0,0,Don Mitchell
11:00:11 45547354mS CMMap: a=4.1 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder resource busy 1, total 64
11:00:11 45547354mS CMMap: a=4.17 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder resource busy 2, total 64
11:00:11 45547356mS CMLineTx: v=0
CMFacility
Line: type=SIPLine 17 Call: lid=17 id=1683 in=0
11:00:11 45547356mS Sip: 17.1683.0 202 SIPTrunk Endpoint(f4d5d36c) received CMFacility
11:00:11 45547360mS CMExtnTx: v=6928, p1=0
CMAlerting
Line: type=IPLine 250 Call: lid=261 id=1680 in=0
Called[Don Mitchell] Type=Default (100) Reason=CMDRdirect Calling[6928] Type=Internal Plan=Default
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=97026432211
IE CMIEDeviceDetail (231) LOCALE=enu HW=14 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x1 rx_gain=32 tx_gain=32 ep_callid=1683 ipaddr=10.0.215.10 apps=0 loc=999 em_loc=999 features2=0x0
Timed: 26/06/14 11:00
11:00:11 45547360mS CMExtnTx: v=6928, p1=8010
CMFacility
Line: type=IPLine 250 Call: lid=261 id=9 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:00:11 45547360mS CMExtnTx: v=6928, p1=8010
CMFacility
Line: type=IPLine 250 Call: lid=261 id=9 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:00:11 45547362mS CMCallEvt: 0.1682.0 -1 BaseEP: DELETE CMEndpoint f4cd23e4 TOTAL NOW=2 CALL_LIST=1
11:00:11 45547365mS H323Evt: SetOperational 203 10.0.215.10:0 to 0
11:00:11 45547365mS H323Evt: SetRfc2833 203: (1) rx payload 101 tx payload 101
11:00:11 45547365mS CMMap: PCG::MapBChan pcp[499]b0r1 cp_b 0 other_cp_b 0 type CGTypeSimple
11:00:11 45547365mS CMMap: PCG::MapBChan pcp[497]b0r1 cp_b 0 other_cp_b 0 type CGTypeSimple
11:00:11 45547366mS CMMap: PCG::MapBChan cp RTP local 10.0.215.10:49152 remote 10.0.215.135:49220 , cp_other RTP local: 10.0.215.10:49154 remote 10.85.9.10:6420
11:00:11 45547366mS CMMap: PCG::MapBChan cp oob 1 rfc_2833 0 , cp_other oob 0, rfc_2833 1, cp behind_nat 0 cp_other behind_nat 0
11:00:11 45547366mS CMMap: PCG::MapBChan rtpRelay Open got rtpRelay ID: 1
11:00:11 45547366mS CMMap: PCG::MapBChan rtpRelay Configure success
11:00:11 45547366mS CMMap: PCG::MapBChan rtpRelay Start success
11:00:11 45547366mS H323Evt: SetOperational 202 10.0.215.10:49152 to 1
11:00:11 45547366mS H323Evt: SetOperational 203 10.0.215.10:49154 to 1
11:00:11 45547367mS CMMap: Mapper:

elayedFreeCodec f56146e4 found cp pcp[497]b0r1 use_reserved_codec 0 local_reserved_codec 0, is_mapped_b 0
11:00:11 45547367mS CMMap: a=4.1 b=0.0 Mapper::FreeCodec freed CMRTVocoder resource busy 1, total 64
11:00:11 45547367mS CMMap: Mapper:

elayedFreeCodec f56016cc found cp pcp[499]b0r1 use_reserved_codec 0 local_reserved_codec 0, is_mapped_b 0
11:00:11 45547367mS CMMap: a=4.17 b=0.0 Mapper::FreeCodec freed CMRTVocoder resource busy 0, total 64
11:00:12 45548945mS CD: CALL: 261.1680.0 BState=Ringing Cut=3 Music=0.0 Aend="Don Mitchell(6928)" (0.0) Bend="Line 17" [Line 17] (0.0) CalledNum=17026432211@sip.emcor.net () CallingNum=6928 (Don Mitchell) Internal=0 Time=21851 AState=Ringing
11:00:21 45557958mS ERR: OSBuf:

ushDown Too far data f6df552b payload f6df5520 amount 14 size 1752 user1 f06344b4 user2 f06345fc
11:00:39 45575194mS H323Evt: Recv: RegistrationRequest 10.0.215.117; Endpoints registered: 24; Endpoints in registration: 0
11:00:39 45575428mS H323Evt: Recv: RegistrationRequest 10.0.215.141; Endpoints registered: 24; Endpoints in registration: 0
11:00:41 45577049mS H323Evt: Recv: RegistrationRequest 10.0.215.115; Endpoints registered: 24; Endpoints in registration: 0
11:00:41 45577229mS H323Evt: Recv: RegistrationRequest 10.0.215.133; Endpoints registered: 24; Endpoints in registration: 0
11:00:41 45577409mS H323Evt: Recv: RegistrationRequest 10.0.215.250; Endpoints registered: 24; Endpoints in registration: 0
11:00:43 45579843mS H323Evt: Recv: RegistrationRequest 10.0.215.231; Endpoints registered: 24; Endpoints in registration: 0
11:00:44 45580281mS H323Evt: Recv: RegistrationRequest 10.0.215.249; Endpoints registered: 24; Endpoints in registration: 0
11:00:45 45581193mS H323Evt: Recv: RegistrationRequest 10.0.215.135; Endpoints registered: 24; Endpoints in registration: 0
11:00:45 45581301mS H323Evt: Recv: RegistrationRequest 10.0.215.138; Endpoints registered: 24; Endpoints in registration: 0
11:00:46 45582738mS H323Evt: Recv: RegistrationRequest 10.0.215.122; Endpoints registered: 24; Endpoints in registration: 0
11:00:46 45582772mS H323Evt: Recv: RegistrationRequest 10.0.215.128; Endpoints registered: 24; Endpoints in registration: 0
11:00:50 45586050mS H323Evt: Recv: RegistrationRequest 10.0.215.113; Endpoints registered: 24; Endpoints in registration: 0
11:00:51 45587242mS H323Evt: Recv: RegistrationRequest 10.0.215.127; Endpoints registered: 24; Endpoints in registration: 0
11:00:51 45587793mS H323Evt: Recv: RegistrationRequest 10.0.215.112; Endpoints registered: 24; Endpoints in registration: 0
11:00:53 45589982mS H323Evt: Recv: RegistrationRequest 10.0.215.253; Endpoints registered: 24; Endpoints in registration: 0
11:00:54 45590520mS H323Evt: Recv: RegistrationRequest 10.0.215.137; Endpoints registered: 24; Endpoints in registration: 0
11:00:55 45591710mS H323Evt: Recv: RegistrationRequest 10.0.215.118; Endpoints registered: 24; Endpoints in registration: 0
11:00:55 45591877mS H323Evt: Recv: RegistrationRequest 10.0.215.252; Endpoints registered: 24; Endpoints in registration: 0
11:00:56 45592800mS H323Evt: Recv: RegistrationRequest 10.0.215.140; Endpoints registered: 24; Endpoints in registration: 0

********** SysMonitor v9.0.3.0 build 941 [connected to 10.0.215.10 (HansenMech-LV)] **********
11:00:56 45592869mS PRN: Monitor Status IP 500 9.0.3.0 build 941
11:00:56 45592870mS PRN: LAW=U PRI=0, BRI=0, ALOG=4, VCOMP=64, MDM=0, WAN=0, MODU=2 LANM=0 CkSRC=0 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=1(TOT=202)
11:00:57 45593832mS H323Evt: Recv: RegistrationRequest 10.0.215.136; Endpoints registered: 24; Endpoints in registration: 0
11:00:57 45593874mS H323Evt: Recv: RegistrationRequest 10.0.215.116; Endpoints registered: 24; Endpoints in registration: 0
11:00:58 45594464mS H323Evt: Recv: RegistrationRequest 10.0.215.130; Endpoints registered: 24; Endpoints in registration: 0
11:00:59 45595664mS H323Evt: Recv: RegistrationRequest 10.0.215.125; Endpoints registered: 24; Endpoints in registration: 0
11:01:01 45597941mS PRN: Optimizing BTree Lists Completed...Started:45597780
11:01:02 45598028mS H323Evt: Recv: RegistrationRequest 10.0.215.119; Endpoints registered: 24; Endpoints in registration: 0
11:01:07 45603832mS CMExtnRxP: v=6901
CMShortCode
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
ShortCode GetSystemInfo (99) = []
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
11:01:07 45603832mS CMExtnEvt: Sara Growcock: ProcessShortCode feature=GetSystemInfo id=
11:01:07 45603832mS CMExtnTxP: v=6901
CMShortCode
Line: type=DigitalExtn 6 Call: lid=0 id=-1 in=0
ShortCode GetSystemInfo (99) = [9.0.3.0 build 941] Calling[HansenMech-LV] Type=Default Plan=Default
Display [IP 500]
Tag type=Text flags=0x1 [1,1,3,1,0,0,0.] [0x31 0x2c 0x31 0x2c 0x33 0x2c 0x31 0x2c 0x30 0x2c 0x30 0x2c 0x30 0x00 ]
Timed: 26/06/14 11:01
11:01:07 45603833mS CMExtnTx: v=6901, p1=0
CMShortCode
Line: type=DigitalExtn 6 Call: lid=0 id=-1 in=0
ShortCode GetSystemInfo (99) = [9.0.3.0 build 941] Calling[HansenMech-LV] Type=Default Plan=Default
Display [IP 500]
Tag type=Text flags=0x1 [1,1,3,1,0,0,0.] [0x31 0x2c 0x31 0x2c 0x33 0x2c 0x31 0x2c 0x30 0x2c 0x30 0x2c 0x30 0x00 ]
Timed: 26/06/14 11:01
11:01:32 45628765mS Sip: SIPDialog f4d79574 created, dialogs 2
11:01:32 45628766mS SIP Reg/Opt Tx: 17
OPTIONS sip:sip.emcor.net SIP/2.0
Via: SIP/2.0/UDP 10.0.215.10:5060;rport;branch=z9hG4bK0666b6e5c9bab18e469e152bbd2ae34a
From: <sip:sip.emcor.net>;tag=188061c2138260f4
To: <sip:sip.emcor.net>
Call-ID: c96e429df542adad520226740865ff08
CSeq: 1431709759 OPTIONS
Contact: <sip:10.0.215.10:5060;transport=udp>
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
Supported: timer
User-Agent: IP Office 9.0.3.0 build 941
Content-Length: 0

11:01:32 45628767mS SIP Tx: UDP 10.0.215.10:5060 -> 10.85.9.21:5060
OPTIONS sip:sip.emcor.net SIP/2.0
Via: SIP/2.0/UDP 10.0.215.10:5060;rport;branch=z9hG4bK0666b6e5c9bab18e469e152bbd2ae34a
From: <sip:sip.emcor.net>;tag=188061c2138260f4
To: <sip:sip.emcor.net>
Call-ID: c96e429df542adad520226740865ff08
CSeq: 1431709759 OPTIONS
Contact: <sip:10.0.215.10:5060;transport=udp>
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
Supported: timer
User-Agent: IP Office 9.0.3.0 build 941
Content-Length: 0

11:01:32 45628870mS SIP Rx: UDP 10.85.9.21:5060 -> 10.0.215.10:5060
SIP/2.0 200 OK
Call-ID: c96e429df542adad520226740865ff08
CSeq: 1431709759 OPTIONS
From: <sip:sip.emcor.net>;tag=188061c2138260f4
To: <sip:sip.emcor.net>;tag=3065334464908257_local.1390390940471_8844044_8856657
Via: SIP/2.0/UDP 10.0.215.10:5060;rport=5060;branch=z9hG4bK0666b6e5c9bab18e469e152bbd2ae34a
Record-Route: <sip:rw-25853dac@10.85.9.21;lr>
Av-Global-Session-ID: e7bcfae0-fd5b-11e3-8bec-d89d677987ec
Server: AVAYA-SM-6.3.4.0.634014
Content-Length: 0

11:01:32 45628872mS SIP Reg/Opt Rx: 17
SIP/2.0 200 OK
Call-ID: c96e429df542adad520226740865ff08
CSeq: 1431709759 OPTIONS
From: <sip:sip.emcor.net>;tag=188061c2138260f4
To: <sip:sip.emcor.net>;tag=3065334464908257_local.1390390940471_8844044_8856657
Via: SIP/2.0/UDP 10.0.215.10:5060;rport=5060;branch=z9hG4bK0666b6e5c9bab18e469e152bbd2ae34a
Record-Route: <sip:rw-25853dac@10.85.9.21;lr>
Av-Global-Session-ID: e7bcfae0-fd5b-11e3-8bec-d89d677987ec
Server: AVAYA-SM-6.3.4.0.634014
Content-Length: 0

11:01:33 45629118mS RES: Thu 26/6/2014 11:01:32 FreeMem=52198468 51401964(3) CachedMem=796504 CMMsg=8(9) Buff=5200 1372 1000 7432 4 Links=29300 BTree=13971 CPU=05.49% CPUStats=2/4/902/19943/21671/0/1 MCR=0 MCW=0
11:01:33 45629118mS RES2: IP 500 9.0.3.0 build 941 Tasks=45 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=83 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=64(TLS=2) TAPI=0 CF=UMNT
11:01:33 45629118mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:01:34 45630196mS H323Evt: Recv: RegistrationRequest 10.0.215.117; Endpoints registered: 24; Endpoints in registration: 0
11:01:34 45630430mS H323Evt: Recv: RegistrationRequest 10.0.215.141; Endpoints registered: 24; Endpoints in registration: 0
11:01:36 45632050mS H323Evt: Recv: RegistrationRequest 10.0.215.115; Endpoints registered: 24; Endpoints in registration: 0
11:01:36 45632228mS H323Evt: Recv: RegistrationRequest 10.0.215.133; Endpoints registered: 24; Endpoints in registration: 0
11:01:36 45632409mS H323Evt: Recv: RegistrationRequest 10.0.215.250; Endpoints registered: 24; Endpoints in registration: 0
11:01:37 45633872mS Sip: SIPDialog f4d79574 deleted, dialogs 1
11:01:38 45634118mS RES: Thu 26/6/2014 11:01:37 FreeMem=52243500 51434772(3) CachedMem=808728 CMMsg=8(9) Buff=5200 1372 1000 7432 4 Links=29304 BTree=13971 CPU=06.47% CPUStats=1/2/902/20058/21671/0/1 MCR=0 MCW=0
11:01:38 45634118mS RES2: IP 500 9.0.3.0 build 941 Tasks=45 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=81 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=64(TLS=2) TAPI=0 CF=UMNT
11:01:38 45634118mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:01:38 45634845mS H323Evt: Recv: RegistrationRequest 10.0.215.231; Endpoints registered: 24; Endpoints in registration: 0
11:01:39 45635280mS H323Evt: Recv: RegistrationRequest 10.0.215.249; Endpoints registered: 24; Endpoints in registration: 0
11:01:40 45636194mS H323Evt: Recv: RegistrationRequest 10.0.215.135; Endpoints registered: 24; Endpoints in registration: 0
11:01:40 45636300mS H323Evt: Recv: RegistrationRequest 10.0.215.138; Endpoints registered: 24; Endpoints in registration: 0
11:01:41 45637741mS H323Evt: Recv: RegistrationRequest 10.0.215.122; Endpoints registered: 24; Endpoints in registration: 0
11:01:41 45637772mS H323Evt: Recv: RegistrationRequest 10.0.215.128; Endpoints registered: 24; Endpoints in registration: 0
11:01:45 45641058mS H323Evt: Recv: RegistrationRequest 10.0.215.113; Endpoints registered: 24; Endpoints in registration: 0
11:01:46 45642244mS H323Evt: Recv: RegistrationRequest 10.0.215.127; Endpoints registered: 24; Endpoints in registration: 0
11:01:46 45642792mS H323Evt: Recv: RegistrationRequest 10.0.215.112; Endpoints registered: 24; Endpoints in registration: 0
11:01:48 45644990mS H323Evt: Recv: RegistrationRequest 10.0.215.253; Endpoints registered: 24; Endpoints in registration: 0
11:01:49 45645517mS H323Evt: Recv: RegistrationRequest 10.0.215.137; Endpoints registered: 24; Endpoints in registration: 0
11:01:50 45646720mS H323Evt: Recv: RegistrationRequest 10.0.215.118; Endpoints registered: 24; Endpoints in registration: 0
11:01:50 45646880mS H323Evt: Recv: RegistrationRequest 10.0.215.252; Endpoints registered: 24; Endpoints in registration: 0
11:01:51 45647804mS H323Evt: Recv: RegistrationRequest 10.0.215.140; Endpoints registered: 24; Endpoints in registration: 0
11:01:52 45648832mS H323Evt: Recv: RegistrationRequest 10.0.215.136; Endpoints registered: 24; Endpoints in registration: 0
11:01:52 45648873mS H323Evt: Recv: RegistrationRequest 10.0.215.116; Endpoints registered: 24; Endpoints in registration: 0
11:01:53 45649466mS H323Evt: Recv: RegistrationRequest 10.0.215.130; Endpoints registered: 24; Endpoints in registration: 0
11:01:54 45650667mS H323Evt: Recv: RegistrationRequest 10.0.215.125; Endpoints registered: 24; Endpoints in registration: 0
11:01:57 45653029mS H323Evt: Recv: RegistrationRequest 10.0.215.119; Endpoints registered: 24; Endpoints in registration: 0

********** SysMonitor v9.0.3.0 build 941 [connected to 10.0.215.10 (HansenMech-LV)] **********
11:01:57 45653711mS PRN: Monitor Status IP 500 9.0.3.0 build 941
11:01:57 45653711mS PRN: LAW=U PRI=0, BRI=0, ALOG=4, VCOMP=64, MDM=0, WAN=0, MODU=2 LANM=0 CkSRC=0 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=1(TOT=202)
11:02:02 45658104mS PRN: Optimizing BTree Lists Completed...Started:45657941
11:02:08 45664674mS CMExtnRxP: v=6901
CMShortCode
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
ShortCode GetSystemInfo (99) = []
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
11:02:08 45664674mS CMExtnEvt: Sara Growcock: ProcessShortCode feature=GetSystemInfo id=
11:02:08 45664674mS CMExtnTxP: v=6901
CMShortCode
Line: type=DigitalExtn 6 Call: lid=0 id=-1 in=0
ShortCode GetSystemInfo (99) = [9.0.3.0 build 941] Calling[HansenMech-LV] Type=Default Plan=Default
Display [IP 500]
Tag type=Text flags=0x1 [1,1,3,1,0,0,0.] [0x31 0x2c 0x31 0x2c 0x33 0x2c 0x31 0x2c 0x30 0x2c 0x30 0x2c 0x30 0x00 ]
Timed: 26/06/14 11:02
11:02:08 45664675mS CMExtnTx: v=6901, p1=0
CMShortCode
Line: type=DigitalExtn 6 Call: lid=0 id=-1 in=0
ShortCode GetSystemInfo (99) = [9.0.3.0 build 941] Calling[HansenMech-LV] Type=Default Plan=Default
Display [IP 500]
Tag type=Text flags=0x1 [1,1,3,1,0,0,0.] [0x31 0x2c 0x31 0x2c 0x33 0x2c 0x31 0x2c 0x30 0x2c 0x30 0x2c 0x30 0x00 ]
Timed: 26/06/14 11:02
11:02:29 45685198mS H323Evt: Recv: RegistrationRequest 10.0.215.117; Endpoints registered: 24; Endpoints in registration: 0
11:02:29 45685432mS H323Evt: Recv: RegistrationRequest 10.0.215.141; Endpoints registered: 24; Endpoints in registration: 0
11:02:31 45687052mS H323Evt: Recv: RegistrationRequest 10.0.215.115; Endpoints registered: 24; Endpoints in registration: 0
11:02:31 45687228mS H323Evt: Recv: RegistrationRequest 10.0.215.133; Endpoints registered: 24; Endpoints in registration: 0
11:02:31 45687410mS H323Evt: Recv: RegistrationRequest 10.0.215.250; Endpoints registered: 24; Endpoints in registration: 0
11:02:33 45689847mS H323Evt: Recv: RegistrationRequest 10.0.215.231; Endpoints registered: 24; Endpoints in registration: 0
11:02:34 45690279mS H323Evt: Recv: RegistrationRequest 10.0.215.249; Endpoints registered: 24; Endpoints in registration: 0
11:02:35 45691204mS H323Evt: Recv: RegistrationRequest 10.0.215.135; Endpoints registered: 24; Endpoints in registration: 0
11:02:35 45691299mS H323Evt: Recv: RegistrationRequest 10.0.215.138; Endpoints registered: 24; Endpoints in registration: 0
11:02:36 45692745mS H323Evt: Recv: RegistrationRequest 10.0.215.122; Endpoints registered: 24; Endpoints in registration: 0
11:02:36 45692781mS H323Evt: Recv: RegistrationRequest 10.0.215.128; Endpoints registered: 24; Endpoints in registration: 0
11:02:40 45696057mS H323Evt: Recv: RegistrationRequest 10.0.215.113; Endpoints registered: 24; Endpoints in registration: 0
11:02:41 45697245mS H323Evt: Recv: RegistrationRequest 10.0.215.127; Endpoints registered: 24; Endpoints in registration: 0
11:02:41 45697800mS H323Evt: Recv: RegistrationRequest 10.0.215.112; Endpoints registered: 24; Endpoints in registration: 0
11:02:43 45699999mS H323Evt: Recv: RegistrationRequest 10.0.215.253; Endpoints registered: 24; Endpoints in registration: 0
11:02:44 45700515mS H323Evt: Recv: RegistrationRequest 10.0.215.137; Endpoints registered: 24; Endpoints in registration: 0
11:02:45 45701721mS H323Evt: Recv: RegistrationRequest 10.0.215.118; Endpoints registered: 24; Endpoints in registration: 0
11:02:45 45701736mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:45 45701736mS PRN: 6970: Digit Pressed 9
11:02:45 45701737mS CMCallEvt: 0.1684.0 -1 BaseEP: NEW CMEndpoint f4cd02c4 TOTAL NOW=3 CALL_LIST=1
11:02:45 45701737mS CMCallEvt: 0.1684.0 -1 Marc Peterson.-1: NEW CMExtnEndpoint f4cd02c4, Name=Marc Peterson, Extn=6970, Phys Extn=6970
11:02:45 45701738mS CMCallEvt: CREATE CALL:203 (f4cc2c64)
11:02:45 45701738mS CMCallEvt: 0.1685.0 -1 BaseEP: NEW CMEndpoint f4c47eac TOTAL NOW=4 CALL_LIST=1
11:02:45 45701741mS CMExtnEvt: Marc Peterson: CMExtnHandler::SetCurrent( id: 0->1684 )
11:02:45 45701741mS CMExtnRx: v=6970, p1=0
CMSetup
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[6970] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIEFastStartInfoData (6) 10 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Marc Peterson
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=Marc Peterson
11:02:45 45701741mS CMCallEvt: 265.1684.0 203 Marc Peterson.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
11:02:45 45701742mS CMExtnEvt: v=15 State, new=Dialling old=Idle,0,0,Marc Peterson
11:02:45 45701742mS CMTARGET: 265.1684.0 203 Marc Peterson.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=6970 dir=out complete=0 ses=0
11:02:45 45701742mS CMTARGET: 265.1684.0 203 Marc Peterson.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
11:02:45 45701743mS CMCallEvt: 265.1684.0 203 Marc Peterson.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
11:02:45 45701746mS CMExtnTx: v=6970, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIESecurityData (253) 2 item(s)
Timed: 26/06/14 11:02
11:02:45 45701747mS CMExtnTx: v=6970, p1=8014
CMFacility
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:02:45 45701747mS CMExtnTx: v=6970, p1=0
CMSetupAck
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Timed: 26/06/14 11:02
11:02:45 45701747mS CMExtnTx: v=6970, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 26/06/14 11:02
11:02:45 45701748mS CMExtnTx: v=6970, p1=8014
CMFacility
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:02:45 45701748mS CMExtnTx: v=6970, p1=8014
CMFacility
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:02:45 45701748mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[9] Type=Default (100) Reason=CMDRdirect Keypad[9]
11:02:45 45701749mS CMTARGET: 265.1684.0 203 Marc Peterson.0: Setting Hard Timer 4000
11:02:45 45701749mS CMTARGET: 265.1684.0 203 Marc Peterson.0: LOOKUP CALL ROUTE: type=100 called_party=9 sub= calling=6970 dir=out complete=0 ses=0
11:02:45 45701749mS CMTARGET: 265.1684.0 203 Marc Peterson.0: ADD TARGET (N): number=9 type=100 depth=1 nobar=1 setorig=1 ses=0
11:02:45 45701750mS CMTARGET: 265.1684.0 203 Marc Peterson.0: SYS SC: 9 2 sc=type=Dial code=9N, num=N callinfop->sending_complete=0 secondary_dialtone=
11:02:45 45701750mS CMARS: FindActiveARSByGroupID GroupID=50 - Found
11:02:45 45701750mS CMARS: MakeCallTarget - Called Number:
11:02:45 45701750mS CMCallEvt: 0.1686.0 -1 BaseEP: NEW CMEndpoint f4cd23e4 TOTAL NOW=5 CALL_LIST=2
11:02:45 45701751mS CMTARGET: 265.1684.0 203 Marc Peterson.0: CancelTimer CMTCDelayedProcessing
11:02:45 45701751mS CMTARGET: 265.1684.0 203 Marc Peterson.0: INITIAL TARGETING SUCCEEDED
11:02:45 45701751mS CMTARGET: 265.1684.0 203 Marc Peterson.0: GetNoAnswerTimer:18
11:02:45 45701752mS CMCallEvt: 0.1685.0 203 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
11:02:45 45701754mS CMCallEvt: 0.1686.0 203 ARS for SIP MAIN: StateChange: END=T CMCSIdle->CMCSOffering
11:02:45 45701754mS CMCallEvt: 0.1685.0 203 TargetingEP: RequestEnd 0.1686.0 203 ARS for SIP MAIN
11:02:45 45701754mS CMTARGET: 265.1684.0 203 Marc Peterson.0: CancelTimer CMTCNoAnswerTimeout
11:02:45 45701755mS CMCallEvt: 0.1686.0 203 ARS for SIP MAIN: StateChange: END=B CMCSOffering->CMCSOverlapRecv
11:02:45 45701756mS CMExtnTx: v=6970, p1=0
CMProgress
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
IE CMIEProgressIndicator (30) cs=CMCSITUT (0), loc=CMLUser (0), pd=CMPDInbandPattern (8)
Display [TRANSFERABLE_SEC_DIAL_TONE]
Timed: 26/06/14 11:02
11:02:45 45701756mS CMARS: FORM: SIP MAIN - Received Number:
11:02:45 45701757mS CMARS: CMARSTargetingPending
11:02:45 45701757mS CMCallEvt: 0.1685.0 -1 TargetingEP: StateChange: END=X CMCSOffering->CMCSDelete
11:02:45 45701757mS CMCallEvt: 0.1685.0 -1 BaseEP: DELETE CMEndpoint f4c47eac TOTAL NOW=4 CALL_LIST=2
11:02:45 45701759mS CD: CALL: 265.1684.0 BState=Idle Cut=2 Music=3.0 Aend="Marc Peterson(6970)" (0.0) Bend="" [] (0.0) CalledNum=9 () CallingNum=6970 (Marc Peterson) Internal=1 Time=21 AState=Dialling
11:02:45 45701760mS H323Evt: SetOperational 204 10.0.215.10:0 to 0
11:02:45 45701761mS CMMap: PCG::AddToneGenerator g D1[1] for cp[500]b0r1 append pcp[501]b0r1 (total 1)
11:02:45 45701761mS CMMap: PlatformConnectionAudioSAP::Bind pcp[501]b0r1 to 0.0
11:02:45 45701761mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[501]b0r1 Configure 0.0
11:02:45 45701761mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[501]b0r1 ConnectIndication 0.0
11:02:45 45701761mS CMMap: a=0.0 b=0.0 pcp[500]b0r1 RTPD1
11:02:45 45701761mS H323Evt: SetOperational 204 10.0.215.10:49156 to 1
11:02:45 45701770mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:45 45701845mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:45 45701882mS H323Evt: Recv: RegistrationRequest 10.0.215.252; Endpoints registered: 24; Endpoints in registration: 0
11:02:46 45702122mS RES: Thu 26/6/2014 11:02:45 FreeMem=52198148 51434772(3) CachedMem=763376 CMMsg=8(9) Buff=5200 1371 999 7432 4 Links=29235 BTree=13968 CPU=10.60% CPUStats=23/33/902/19127/21671/0/0 MCR=0 MCW=0
11:02:46 45702122mS RES2: IP 500 9.0.3.0 build 941 Tasks=45 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=84 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=64(TLS=2) TAPI=0 CF=UMNT
11:02:46 45702122mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:02:46 45702207mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:46 45702207mS PRN: 6970: Digit Pressed 7
11:02:46 45702208mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[7] Type=Default (100) Reason=CMDRdirect Keypad[7]
11:02:46 45702208mS CMARS: FORM: SIP MAIN - Received Number: 7
11:02:46 45702208mS CMARS: CMARSTargetingPending
11:02:46 45702210mS CMMap: a=0.0 b=0.0 pcp[500]b0r1 RTPD0
11:02:46 45702210mS H323Evt: SetOperational 204 10.0.215.10:49156 to 0
11:02:46 45702277mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:46 45702549mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:46 45702549mS PRN: 6970: Digit Pressed 0
11:02:46 45702550mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
11:02:46 45702550mS CMARS: FORM: SIP MAIN - Received Number: 70
11:02:46 45702550mS CMARS: CMARSTargetingPending
11:02:46 45702650mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:46 45702808mS H323Evt: Recv: RegistrationRequest 10.0.215.140; Endpoints registered: 24; Endpoints in registration: 0
11:02:47 45703200mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:47 45703200mS PRN: 6970: Digit Pressed 2
11:02:47 45703200mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[2] Type=Default (100) Reason=CMDRdirect Keypad[2]
11:02:47 45703201mS CMARS: FORM: SIP MAIN - Received Number: 702
11:02:47 45703201mS CMARS: CMARSTargetingPending
11:02:47 45703290mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:47 45703832mS H323Evt: Recv: RegistrationRequest 10.0.215.136; Endpoints registered: 24; Endpoints in registration: 0
11:02:47 45703871mS H323Evt: Recv: RegistrationRequest 10.0.215.116; Endpoints registered: 24; Endpoints in registration: 0
11:02:48 45704468mS H323Evt: Recv: RegistrationRequest 10.0.215.130; Endpoints registered: 24; Endpoints in registration: 0
11:02:49 45705670mS H323Evt: Recv: RegistrationRequest 10.0.215.125; Endpoints registered: 24; Endpoints in registration: 0
11:02:49 45705812mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:49 45705812mS PRN: 6970: Digit Pressed 3
11:02:49 45705812mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[3] Type=Default (100) Reason=CMDRdirect Keypad[3]
11:02:49 45705813mS CMARS: FORM: SIP MAIN - Received Number: 7023
11:02:49 45705813mS CMARS: CMARSTargetingPending
11:02:49 45705897mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:50 45706137mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:50 45706137mS PRN: 6970: Digit Pressed 6
11:02:50 45706138mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[6] Type=Default (100) Reason=CMDRdirect Keypad[6]
11:02:50 45706138mS CMARS: FORM: SIP MAIN - Received Number: 70236
11:02:50 45706138mS CMARS: CMARSTargetingPending
11:02:50 45706210mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:50 45706447mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:50 45706447mS PRN: 6970: Digit Pressed 2
11:02:50 45706448mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[2] Type=Default (100) Reason=CMDRdirect Keypad[2]
11:02:50 45706448mS CMARS: FORM: SIP MAIN - Received Number: 702362
11:02:50 45706448mS CMARS: CMARSTargetingPending
11:02:50 45706547mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:51 45707634mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:51 45707634mS PRN: 6970: Digit Pressed 9
11:02:51 45707634mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[9] Type=Default (100) Reason=CMDRdirect Keypad[9]
11:02:51 45707635mS CMARS: FORM: SIP MAIN - Received Number: 7023629
11:02:51 45707635mS CMARS: CMARSTargetingPending
11:02:51 45707735mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:52 45708030mS H323Evt: Recv: RegistrationRequest 10.0.215.119; Endpoints registered: 24; Endpoints in registration: 0
11:02:52 45708083mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:52 45708083mS PRN: 6970: Digit Pressed 2
11:02:52 45708084mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[2] Type=Default (100) Reason=CMDRdirect Keypad[2]
11:02:52 45708084mS CMARS: FORM: SIP MAIN - Received Number: 70236292
11:02:52 45708084mS CMARS: CMARSTargetingPending
11:02:52 45708122mS RES: Thu 26/6/2014 11:02:51 FreeMem=52199428 51434772(3) CachedMem=764656 CMMsg=8(9) Buff=5200 1371 999 7433 4 Links=29251 BTree=13968 CPU=07.59% CPUStats=2/6/902/19706/21671/0/0 MCR=0 MCW=0
11:02:52 45708122mS RES2: IP 500 9.0.3.0 build 941 Tasks=45 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=84 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=64(TLS=2) TAPI=0 CF=UMNT
11:02:52 45708122mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:02:52 45708171mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:52 45708642mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:52 45708642mS PRN: 6970: Digit Pressed 0
11:02:52 45708643mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
11:02:52 45708643mS CMARS: FORM: SIP MAIN - Received Number: 702362920
11:02:52 45708644mS CMARS: CMARSTargetingPending
11:02:52 45708704mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:52 45708788mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:52 45708788mS PRN: 6970: Digit Pressed 0
11:02:52 45708789mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
11:02:52 45708789mS CMARS: FORM: SIP MAIN - Received Number: 7023629200
11:02:52 45708789mS CMARS: CMARSTargetingPending
11:02:52 45708881mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:02:57 45713750mS CMARS: Case 1 - dial_delay_time: 4000 has expired - Resolve what we might have - Called Number: 7023629200 Addr: f4cd23e4
11:02:57 45713750mS CMARS: FORM: SIP MAIN - Received Number: 7023629200
11:02:57 45713750mS CMARS: FOUND A SHORT CODE - short_code: xxxxxxxxxx; - Tel: 1N"@sip.emcor.net" - Called_Party: 17023629200@sip.emcor.net - Line Group Id: 0
11:02:57 45713750mS CMARS: FindActiveARSByGroupID GroupID=0 - Not Found
11:02:57 45713750mS CMLRQ: FindActiveLRQByGroupID GroupID=0 - Not Found
11:02:57 45713751mS Sip: License, Valid 1, Available 15, Consumed 1
11:02:57 45713751mS CMCallEvt: 0.1687.0 -1 BaseEP: NEW CMEndpoint f4d8ac74 TOTAL NOW=5 CALL_LIST=2
11:02:57 45713751mS Sip: SIPDialog f4d79574 created, dialogs 2
11:02:57 45713753mS CMARS: FOUND LINE - Line Id: 17 - using line group id: 0 - Called Number: 17023629200@sip.emcor.net - Calling Number: 6970
11:02:57 45713753mS CMARS: SEND Setup TO LINE
11:02:57 45713754mS CMCallEvt: 17.1687.0 203 SIPTrunk Endpoint: StateChange: END=child CMCSIdle->CMCSOffering
11:02:57 45713755mS CMLineTx: v=0
CMSetup
Line: type=SIPLine 17 Call: lid=17 id=1687 in=0
Called[17023629200@sip.emcor.net] Type=Default (100) Reason=CMDRdirect SndComp Calling[6970] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
CallingName.Invoke.CodePageISO8859-1
invokeId 14789
user 'Marc Peterson' presentation Allowed
IE CMIEFastStartInfoData (6) 6 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Marc Peterson
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=Marc Peterson
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=Marc Peterson
IE CMIERespondingPartyKName (229)(Type=CMNameDefault) name=Marc Peterson
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:4) number=6970
IE CMIEDeviceDetail (231) LOCALE=enu HW=14 VER=9 class=CMDeviceH323Phone type=38 number=8014 channel=0 features=0x10000420 rx_gain=0 tx_gain=32 ep_callid=1684 ipaddr=10.0.215.10 apps=0 loc=2 em_loc=2 features2=0x0
IE CMIEMohSourceId (247) MOH Source = 255
IE CMIESecurityData (253) 2 item(s)
Locale: enu
11:02:57 45713755mS Sip: 17.1687.0 203 SIPTrunk Endpoint(f4d8ac74) received CMSetup
11:02:57 45713756mS Sip: 17.1687.0 203 SIPTrunk Endpoint(f4d79574) SetLocalRTPAddress to 10.0.215.10:49158
11:02:57 45713758mS SIP Call Tx: 17
INVITE sip:17023629200@sip.emcor.net SIP/2.0
Via: SIP/2.0/UDP 10.0.215.10:5060;rport;branch=z9hG4bK105b9bf5aa0510b3196e41f9940bbb5a
From: "Marc Peterson" <sip:6970@sip.emcor.net>;tag=db42906cacd8725d
To: <sip:17023629200@sip.emcor.net>
Call-ID: d19ce15aef61f5ebe11558584a518526
CSeq: 2109473882 INVITE
Contact: "Marc Peterson" <sip:7029206970@10.0.215.10:5060;transport=udp>
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
Content-Type: application/sdp
Supported: timer
User-Agent: IP Office 9.0.3.0 build 941
Content-Length: 249

v=0
o=UserA 4271569619 3843033115 IN IP4 10.0.215.10
s=Session SDP
c=IN IP4 10.0.215.10
t=0 0
m=audio 49158 RTP/AVP 18 0 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
11:02:57 45713758mS SIP Tx: UDP 10.0.215.10:5060 -> 10.85.9.21:5060
INVITE sip:17023629200@sip.emcor.net SIP/2.0
Via: SIP/2.0/UDP 10.0.215.10:5060;rport;branch=z9hG4bK105b9bf5aa0510b3196e41f9940bbb5a
From: "Marc Peterson" <sip:6970@sip.emcor.net>;tag=db42906cacd8725d
To: <sip:17023629200@sip.emcor.net>
Call-ID: d19ce15aef61f5ebe11558584a518526
CSeq: 2109473882 INVITE
Contact: "Marc Peterson" <sip:7029206970@10.0.215.10:5060;transport=udp>
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
Content-Type: application/sdp
Supported: timer
User-Agent: IP Office 9.0.3.0 build 941
Content-Length: 249

v=0
o=UserA 4271569619 3843033115 IN IP4 10.0.215.10
s=Session SDP
c=IN IP4 10.0.215.10
t=0 0
m=audio 49158 RTP/AVP 18 0 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
11:02:57 45713759mS CD: CALL: 265.1684.0 BState=Idle Cut=2 Music=0.0 Aend="Marc Peterson(6970)" (0.0) Bend="" [Line 17] (0.0) CalledNum=97023629200 () CallingNum=6970 (Marc Peterson) Internal=1 Time=12021 AState=Dialling
11:02:57 45713849mS SIP Rx: UDP 10.85.9.21:5060 -> 10.0.215.10:5060
SIP/2.0 100 Trying
Call-ID: d19ce15aef61f5ebe11558584a518526
CSeq: 2109473882 INVITE
From: "Marc Peterson" <sip:6970@sip.emcor.net>;tag=db42906cacd8725d
To: <sip:17023629200@sip.emcor.net>
Via: SIP/2.0/UDP 10.0.215.10:5060;rport=5060;branch=z9hG4bK105b9bf5aa0510b3196e41f9940bbb5a
Content-Length: 0

11:02:57 45713850mS SIP Call Rx: 17
SIP/2.0 100 Trying
Call-ID: d19ce15aef61f5ebe11558584a518526
CSeq: 2109473882 INVITE
From: "Marc Peterson" <sip:6970@sip.emcor.net>;tag=db42906cacd8725d
To: <sip:17023629200@sip.emcor.net>
Via: SIP/2.0/UDP 10.0.215.10:5060;rport=5060;branch=z9hG4bK105b9bf5aa0510b3196e41f9940bbb5a
Content-Length: 0

11:02:57 45713851mS CMLineRx: v=0
CMProceeding
Line: type=SIPLine 17 Call: lid=17 id=1687 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[6970] Type=Internal Plan=Default
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=97023629200
IE CMIEDeviceDetail (231) LOCALE=enu HW=14 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=2 features=0x1 rx_gain=32 tx_gain=32 ep_callid=1687 ipaddr=10.0.215.10 apps=0 loc=999 em_loc=999 features2=0x0
11:02:57 45713851mS CMARS: LINE ep Received: CMProceeding - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
11:02:57 45713989mS SIP Rx: UDP 10.85.9.21:5060 -> 10.0.215.10:5060
SIP/2.0 604 Does Not Exist Anywhere
To: <sip:17023629200@sip.emcor.net>;tag=1c1130231932
P-Location: SM;origlocname="Hansen";origsiglocname="Hansen";origmedialocname="Hansen";termlocname="Ashburn";termsiglocname="Ashburn";termmedialocname="Ashburn";smaccounting="true"
Server: Audiocodes-Sip-Gateway-Mediant 1000 - MSBG/v.6.00AL.022.004 AVAYA-SM-6.3.4.0.634014
Av-Global-Session-ID: 1a639800-fd5c-11e3-8bec-d89d677987ec
Record-Route: <sip:rw-25853dac@10.85.9.21;lr;transport=TCP>
Record-Route: <sip:10.85.9.20:15060;transport=tcp;ibmsid=local.1390390940471_8844106_8856719;lr;ibmdrr>
Record-Route: <sip:10.85.9.20:15060;transport=udp;ibmsid=local.1390390940471_8844106_8856719;lr;ibmdrr>
Record-Route: <sip:rw-25853dac@10.85.9.21;lr>
From: "Marc Peterson" <sip:6970@sip.emcor.net>;tag=db42906cacd8725d
Call-ID: d19ce15aef61f5ebe11558584a518526
CSeq: 2109473882 INVITE
Via: SIP/2.0/UDP 10.0.215.10:5060;rport=5060;branch=z9hG4bK105b9bf5aa0510b3196e41f9940bbb5a
Content-Length: 0

11:02:57 45713992mS SIP Call Rx: 17
SIP/2.0 604 Does Not Exist Anywhere
To: <sip:17023629200@sip.emcor.net>;tag=1c1130231932
P-Location: SM;origlocname="Hansen";origsiglocname="Hansen";origmedialocname="Hansen";termlocname="Ashburn";termsiglocname="Ashburn";termmedialocname="Ashburn";smaccounting="true"
Server: Audiocodes-Sip-Gateway-Mediant 1000 - MSBG/v.6.00AL.022.004 AVAYA-SM-6.3.4.0.634014
Av-Global-Session-ID: 1a639800-fd5c-11e3-8bec-d89d677987ec
Record-Route: <sip:rw-25853dac@10.85.9.21;lr;transport=TCP>
Record-Route: <sip:10.85.9.20:15060;transport=tcp;ibmsid=local.1390390940471_8844106_8856719;lr;ibmdrr>
Record-Route: <sip:10.85.9.20:15060;transport=udp;ibmsid=local.1390390940471_8844106_8856719;lr;ibmdrr>
Record-Route: <sip:rw-25853dac@10.85.9.21;lr>
From: "Marc Peterson" <sip:6970@sip.emcor.net>;tag=db42906cacd8725d
Call-ID: d19ce15aef61f5ebe11558584a518526
CSeq: 2109473882 INVITE
Via: SIP/2.0/UDP 10.0.215.10:5060;rport=5060;branch=z9hG4bK105b9bf5aa0510b3196e41f9940bbb5a
Content-Length: 0

11:02:57 45713996mS SIP Call Tx: 17
ACK sip:17023629200@sip.emcor.net SIP/2.0
Via: SIP/2.0/UDP 10.0.215.10:5060;rport;branch=z9hG4bK105b9bf5aa0510b3196e41f9940bbb5a
Route: <sip:rw-25853dac@10.85.9.21;lr>
Route: <sip:10.85.9.20:15060;transport=udp;ibmsid=local.1390390940471_8844106_8856719;lr;ibmdrr>
Route: <sip:10.85.9.20:15060;transport=tcp;ibmsid=local.1390390940471_8844106_8856719;lr;ibmdrr>
Route: <sip:rw-25853dac@10.85.9.21;lr;transport=TCP>
From: "Marc Peterson" <sip:6970@sip.emcor.net>;tag=db42906cacd8725d
To: <sip:17023629200@sip.emcor.net>;tag=1c1130231932
Call-ID: d19ce15aef61f5ebe11558584a518526
CSeq: 2109473882 ACK
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
User-Agent: IP Office 9.0.3.0 build 941
Content-Length: 0

11:02:57 45713996mS SIP Tx: UDP 10.0.215.10:5060 -> 10.85.9.21:5060
ACK sip:17023629200@sip.emcor.net SIP/2.0
Via: SIP/2.0/UDP 10.0.215.10:5060;rport;branch=z9hG4bK105b9bf5aa0510b3196e41f9940bbb5a
Route: <sip:rw-25853dac@10.85.9.21;lr>
Route: <sip:10.85.9.20:15060;transport=udp;ibmsid=local.1390390940471_8844106_8856719;lr;ibmdrr>
Route: <sip:10.85.9.20:15060;transport=tcp;ibmsid=local.1390390940471_8844106_8856719;lr;ibmdrr>
Route: <sip:rw-25853dac@10.85.9.21;lr;transport=TCP>
From: "Marc Peterson" <sip:6970@sip.emcor.net>;tag=db42906cacd8725d
To: <sip:17023629200@sip.emcor.net>;tag=1c1130231932
Call-ID: d19ce15aef61f5ebe11558584a518526
CSeq: 2109473882 ACK
Max-Forwards: 70
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
User-Agent: IP Office 9.0.3.0 build 941
Content-Length: 0

11:02:57 45713997mS CMLineRx: v=0
CMReleaseComp
Line: type=SIPLine 17 Call: lid=17 id=1687 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[6970] Type=Internal Plan=Default
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=97023629200
IE CMIEDeviceDetail (231) LOCALE=enu HW=14 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=2 features=0x1 rx_gain=32 tx_gain=32 ep_callid=1687 ipaddr=10.0.215.10 apps=0 loc=999 em_loc=999 features2=0x0
Cause=1, Unallocated (unassigned) number
11:02:57 45713997mS CMARS: LINE ep Received: CMReleaseComp - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
11:02:57 45713998mS CMLineTx: v=0
CMReleaseComp
Line: type=SIPLine 17 Call: lid=17 id=1687 in=0
Cause=16, Normal call clearing
11:02:57 45713998mS Sip: 17.1687.0 -1 SIPTrunk Endpoint(f4d8ac74) received CMReleaseComp
11:02:57 45713998mS Sip: SIPDialog f4d79574 deleted, dialogs 1
11:02:57 45713999mS CMCallEvt: 17.1687.0 -1 SIPTrunk Endpoint: StateChange: END=X CMCSOffering->CMCSDelete
11:02:57 45713999mS CMARS: Target: Short_Code: xxxxxxxxxx; - Line_Group_ID: 0 has been set to: CMARS_OUTOFSERVICE_ALL
11:02:57 45713999mS CMARS: 0.1686.0 203 ARS for SIP MAIN: DropCall() - ABOUT TO SEND CMReleaseComp
11:02:57 45713999mS CMCallEvt: 0.1686.0 203 ARS for SIP MAIN: StateChange: END=B CMCSOverlapRecv->CMCSCompleted
11:02:58 45714000mS CMExtnTx: v=6970, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 26/06/14 11:02
11:02:58 45714000mS CMExtnTx: v=6970, p1=8014
CMFacility
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:02:58 45714001mS CMLOGGING: CALL:2014/06/2611:02,00:00:00,000,6970,O,97023629200,97023629200,MarcPeterson,,,1,,""n/a,0
11:02:58 45714001mS CD: CALL: 265.1684.0 BState=Disconnecting Cut=0 Music=0.0 Aend="Marc Peterson(6970)" (0.0) Bend="" [] (0.0) CalledNum=97023629200 () CallingNum=6970 (Marc Peterson) Internal=1 Time=12263 AState=Dialling
11:02:58 45714002mS CD: CALL: 265.1684.0 Deleted
11:02:58 45714004mS CMExtnEvt: Marc Peterson: CALL LOST (CMCauseUnallocatedNumber)
11:02:58 45714004mS CMExtnEvt: Marc Peterson: Extn(6970) Calling Party Number(6970) Type(CMNTypeInternal)
11:02:58 45714004mS CMCallEvt: 265.1684.0 -1 Marc Peterson.0: StateChange: END=X CMCSDialling->CMCSCompletedTone
11:02:58 45714006mS CMExtnTx: v=6970, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 26/06/14 11:02
11:02:58 45714006mS CMExtnTx: v=6970, p1=8014
CMFacility
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:02:58 45714007mS CMExtnEvt: v=15 State, new=CMESCompleted old=Dialling,0,0,Marc Peterson
11:02:58 45714007mS CMARS: CMARSEndpoint::CallLost(cause=1) - Address: 0.1686.0 -1 ARS for SIP MAIN - Call State: CMCSCompleted
11:02:58 45714008mS CMCallEvt: 0.1686.0 -1 ARS for SIP MAIN: StateChange: END=X CMCSCompleted->CMCSDelete
11:02:58 45714008mS CMCallEvt: END CALL:203 (f4cc2c64)
11:02:58 45714009mS CMCallEvt: 0.1686.0 -1 BaseEP: DELETE CMEndpoint f4cd23e4 TOTAL NOW=4 CALL_LIST=1
11:02:58 45714009mS CMCallEvt: 17.1687.0 -1 BaseEP: DELETE CMEndpoint f4d8ac74 TOTAL NOW=3 CALL_LIST=1
11:02:58 45714011mS CMMap: PCG::AddToneGenerator g B3[6] for cp[500]b0r1 append pcp[503]b0r1 (total 1)
11:02:58 45714011mS CMMap: a=4.1 b=0.0 IP::ReserveCodec pcp[503]b0r1 allocated CMRTVocoder resource busy 1, total 64, codec type 5
11:02:58 45714012mS CMMap: a=21.42 b=0.0 DTMF::AllocateRAS allocated CMRTVoicemail resource busy 1, total 45
11:02:58 45714013mS CMMap: a=21.42 b=1.65535 T
11:02:58 45714013mS CMMap: a=21.42 b=4.1 M22
11:02:58 45714013mS CMMap: PlatformConnectionAudioSAP::Bind pcp[503]b0r1 to 4.1
11:02:58 45714013mS CMMap: PlatformConnectionAudioSAP::ConnectVoice (connect) pcp[503]b0r1 echo_cancellation set to 0
11:02:58 45714013mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[503]b0r1 Configure 4.1
11:02:58 45714013mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[503]b0r1 ConnectIndication 4.1
11:02:58 45714014mS CMMap: a=0.0 b=0.0 pcp[500]b0r1 RTPB3
11:02:58 45714014mS H323Evt: SetOperational 204 10.0.215.10:49156 to 1
11:02:58 45714122mS RES: Thu 26/6/2014 11:02:57 FreeMem=52174604 51401748(4) CachedMem=772856 CMMsg=8(9) Buff=5200 1362 999 7433 4 Links=29227 BTree=13969 CPU=11.19% CPUStats=21/30/902/18811/21671/0/0 MCR=0 MCW=0
11:02:58 45714122mS RES2: IP 500 9.0.3.0 build 941 Tasks=45 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=88 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=64(TLS=2) TAPI=0 CF=UMNT
11:02:58 45714122mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)

********** SysMonitor v9.0.3.0 build 941 [connected to 10.0.215.10 (HansenMech-LV)] **********
11:02:58 45714554mS PRN: Monitor Status IP 500 9.0.3.0 build 941
11:02:58 45714554mS PRN: LAW=U PRI=0, BRI=0, ALOG=4, VCOMP=64, MDM=0, WAN=0, MODU=2 LANM=0 CkSRC=0 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=1(TOT=203)
11:02:58 45714739mS H323Evt: RTP(50t): 10.0.215.10/49156 10.0.215.113/49406 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=12979 SENT=50 (avg size=161) RECV=24 (avg size=160)
11:03:01 45717862mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:03:01 45717864mS CMExtnTx: v=6970, p1=8014
CMFacility
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:03:01 45717864mS CMExtnRx: v=6970, p1=0
CMReleaseComp
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
11:03:01 45717865mS CMCallEvt: 265.1684.0 -1 Marc Peterson.0: StateChange: END=X CMCSCompletedTone->CMCSCompleted
11:03:01 45717866mS CMExtnTx: v=6970, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=265 id=1684 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 26/06/14 11:03
11:03:01 45717866mS CMExtnEvt: v=15 State, new=PortRecoverDelay old=CMESCompleted,0,0,Marc Peterson
11:03:01 45717867mS CMExtnEvt: Marc Peterson: CALL LOST (CMCauseForceClear)
11:03:01 45717868mS CMExtnEvt: Marc Peterson: Extn(6970) Calling Party Number(6970) Type(CMNTypeInternal)
11:03:01 45717868mS CMExtnEvt: Marc Peterson: CMExtnHandler::SetCurrent( id: 1684->0 )
11:03:01 45717868mS CMCallEvt: 265.1684.0 -1 Marc Peterson.-1: StateChange: END=X CMCSCompleted->CMCSDelete
11:03:01 45717869mS CMTARGET: 265.1684.0 -1 BaseEP: ~CMTargetHandler f4cd6f34 ep f4cd02c4
11:03:01 45717869mS CMCallEvt: 265.1684.0 -1 BaseEP: DELETE CMEndpoint f4cd02c4 TOTAL NOW=2 CALL_LIST=1
11:03:01 45717870mS CMMap: a=0.0 b=0.0 pcp[500]b0r1 RTPB0
11:03:01 45717870mS H323Evt: SetOperational 204 10.0.215.10:49156 to 0
11:03:01 45717871mS CMMap: a=21.42 b=4.1 M02
11:03:01 45717871mS CMMap: a=21.42 b=0.0 T0
11:03:01 45717872mS CMMap: a=21.42 b=0.0 DTMF::~DTMF freed CMRTUnknown resource busy 0, total 45
11:03:01 45717872mS H323Evt: RTP(END): 10.0.215.10/49156 10.0.215.113/49406 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=16112 SENT=206 RECV=180 RTdelay=0 jitter=0 loss=0 remotejitter=0 remoteloss=0
11:03:01 45717874mS CMMap: a=4.1 b=0.0 IP::FreeCodec pcp[503]b0r1 freed CMRTVocoder resource busy 1, total 64
11:03:02 45718264mS PRN: Optimizing BTree Lists Completed...Started:45718104
11:03:02 45718642mS CMCallPkt: v=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIECCMSMessage (5) unknown
11:03:02 45718642mS PRN: 6970: Digit Pressed 9
11:03:02 45718643mS CMCallEvt: 0.1688.0 -1 BaseEP: NEW CMEndpoint f4cd02c4 TOTAL NOW=3 CALL_LIST=1
11:03:02 45718643mS CMCallEvt: 0.1688.0 -1 Marc Peterson.-1: NEW CMExtnEndpoint f4cd02c4, Name=Marc Peterson, Extn=6970, Phys Extn=6970
11:03:02 45718644mS CMCallEvt: CREATE CALL:204 (f4cc2c64)
11:03:02 45718644mS CMCallEvt: 0.1689.0 -1 BaseEP: NEW CMEndpoint f4c47eac TOTAL NOW=4 CALL_LIST=1
11:03:02 45718646mS CMExtnEvt: Marc Peterson: CMExtnHandler::SetCurrent( id: 0->1688 )
11:03:02 45718647mS CMExtnEvt: v=15 State, new=Idle old=PortRecoverDelay,0,0,Marc Peterson
11:03:02 45718648mS CMExtnRx: v=6970, p1=0
CMSetup
Line: type=IPLine 250 Call: lid=265 id=1688 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[6970] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIEFastStartInfoData (6) 10 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Marc Peterson
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=Marc Peterson
11:03:02 45718648mS CMCallEvt: 265.1688.0 204 Marc Peterson.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
11:03:02 45718648mS CMExtnEvt: v=15 State, new=Dialling old=Idle,0,0,Marc Peterson
11:03:02 45718648mS CMTARGET: 265.1688.0 204 Marc Peterson.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=6970 dir=out complete=0 ses=0
11:03:02 45718649mS CMTARGET: 265.1688.0 204 Marc Peterson.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
11:03:02 45718649mS CMCallEvt: 265.1688.0 204 Marc Peterson.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
11:03:02 45718653mS CMExtnTx: v=6970, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=265 id=1688 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIESecurityData (253) 2 item(s)
Timed: 26/06/14 11:03
11:03:02 45718653mS CMExtnTx: v=6970, p1=8014
CMFacility
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:03:02 45718653mS CMExtnTx: v=6970, p1=0
CMSetupAck
Line: type=IPLine 250 Call: lid=265 id=1688 in=0
Timed: 26/06/14 11:03
11:03:02 45718654mS CMExtnTx: v=6970, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=265 id=1688 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 26/06/14 11:03
11:03:02 45718654mS CMExtnTx: v=6970, p1=8014
CMFacility
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:03:02 45718654mS CMExtnTx: v=6970, p1=8014
CMFacility
Line: type=IPLine 250 Call: lid=265 id=15 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:03:02 45718655mS CMExtnRx: v=6970, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=265 id=1688 in=0
Called[9] Type=Default (100) Reason=CMDRdirect Keypad[9]
11:03:02 45718655mS CMTARGET: 265.1688.0 204 Marc Peterson.0: Setting Hard Timer 4000
11:03:02 45718655mS CMTARGET: 265.1688.0 204 Marc Peterson.0: LOOKUP CALL ROUTE: type=100 called_party=9 sub= calling=6970 dir=out complete=0 ses=0
11:03:02 45718656mS CMTARGET: 265.1688.0 204 Marc Peterson.0: ADD TARGET (N): number=9 type=100 depth=1 nobar=1 setorig=1 ses=0
11:03:02 45718656mS CMTARGET: 265.1688.0 204 Marc Peterson.0: SYS SC: 9 2 sc=type=Dial code=9N, num=N callinfop->sending_complete=0 secondary_dialtone=
11:03:02 45718656mS CMARS: FindActiveARSByGroupID GroupID=50 - Found
11:03:02 45718656mS CMARS: MakeCallTarget - Called Number:
11:03:02

SupportDude · Jun 26, 2014

Can you tell us which call(s) in the trace experienced the problem?

-SD-

http://www.mysupportguy.net

Tek-Tips is the largest IT community on the Internet today!

Members share and learn making Tek-Tips Forums the best source of peer-reviewed technical information on the Internet!

Avaya IP Office SIP Trunking disconnects on outgoing calls only. Help Please.

RodneyMcSnow

Technical User

SupportDude

Technical User

RodneyMcSnow

Technical User

SupportDude

Technical User

Similar threads

Part and Inventory Search

Sponsor