Ext:125 name Bench is the problem. This monitor is I made a call to ext:101 then lifted the handset
UNICODE-UTF8
enu
********** SysMonitor v9.0.3.0 build 941 **********
********** contact made with 192.168.4.199 at 11:16:21 30/6/2014 **********
********** System (192.168.4.199) has been up and running for 40days, 23hrs, 43mins and 11secs(3541391078mS) **********
********** Warning: TEXT File Logging selected **********
********** Warning: TEXT Logging to Log File Name not Set File: STOPPED on 30/6/2014 11:16:21 **********
3541391078mS PRN: Monitor Started IP=192.168.4.174 IP 500 V2 9.0.3.0 build 941 VoxVar
(IP Office: Supports Unicode, System Locale is default)
3541391078mS PRN: LAW=U PRI=0, BRI=0, ALOG=4, VCOMP=10, MDM=0, WAN=0, MODU=0 LANM=0 CkSRC=0 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=0(TOT=1823)
11:16:26 3541391173mS RES: Mon 30/6/2014 11:16:26 FreeMem=53736208 52848056(1) CachedMem=888152 CMMsg=9(10) Buff=5200 1360 1000 7438 5 Links=12820 BTree=14410 CPU=02.32% CPUStats=1/3/5238/21110/23084/0/0 MCR=0 MCW=0
11:16:26 3541391173mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=68 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=24(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:16:26 3541391173mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:16:29 3541394078mS PRN: +++ START OF ALARM LOG DUMP +++
11:16:29 3541394078mS PRN: ALARM: 18/07/2012 16:43:45 IP 500 V2 8.0(42) <WATCHDOG > CRIT RAISED addr=00000000 d=0 pc=f0ad0f6c f0ad1090 f093f5c8 f0ad0e60 f0ad1a8c f014c4e0
11:16:29 3541394078mS PRN: +++ END OF ALARM LOG DUMP +++
11:16:30 3541395078mS PRN: +++ START OF UDP MONITOR CLIENT DUMP +++
11:16:30 3541395078mS PRN: CLIENT: IPAddress=192.168.4.195 UDPPort=57724 LastReceived=3541393576(1502) LastSent=3541393576(1502) LastOldUpdate=3541351591(43487) SentPackets=10 MissedPackets=0 OldSentPackets=45 OldMissedPackets=0
11:16:30 3541395078mS PRN: CLIENT: IPAddress=192.168.4.174 UDPPort=57545 LastReceived=3541391092(3986) LastSent=3541395078(0) LastOldUpdate=3541391077(4001) SentPackets=18 MissedPackets=0 OldSentPackets=0 OldMissedPackets=0
11:16:30 3541395078mS PRN: ++++ END OF UDP MONITOR CLIENT DUMP ++++
11:16:30 3541395685mS H323Evt: Shared tcp socket for line 18 disconnected
11:16:31 3541396174mS RES: Mon 30/6/2014 11:16:31 FreeMem=53727824 52848056(1) CachedMem=879768 CMMsg=9(10) Buff=5200 1358 1000 7440 5 Links=12819 BTree=14410 CPU=03.77% CPUStats=1/3/5238/20972/23084/0/0 MCR=0 MCW=0
11:16:31 3541396174mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=53 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=71 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=24(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:16:31 3541396174mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:16:31 3541396278mS PRN: +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
11:16:31 3541396278mS PRN: + loader: 1.33
11:16:31 3541396278mS PRN: + cpu: id 12 board 4 pld 25 type c10 options ac02
11:16:31 3541396278mS PRN: + cpu: sn 11WZ261000A8
11:16:31 3541396278mS PRN: + fpga: id 1 issue 0 build 827
11:16:31 3541396278mS PRN: +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
11:16:31 3541396278mS PRN: ++++++++++++++++++++ LIST OF MODULES ++++++++++++++++++++
11:16:31 3541396278mS PRN: +------------------------------------------------------------
11:16:31 3541396278mS PRN: + Slot 1: Base COMBO6210 Board=0x02 PLD=0x04
11:16:31 3541396278mS PRN: + Mezzanine ATM4 V2 Board=0x01 PLD=0x04
11:16:31 3541396278mS PRN: +------------------------------------------------------------
11:16:31 3541396279mS PRN: + Slot 2: Base TCM8 Board=0x01 PLD=0x29
11:16:31 3541396279mS PRN: + Mezzanine NONE
11:16:31 3541396279mS PRN: +------------------------------------------------------------
11:16:31 3541396279mS PRN: + Slot 3: Base NONE
11:16:31 3541396279mS PRN: + Mezzanine NONE
11:16:31 3541396279mS PRN: +------------------------------------------------------------
11:16:31 3541396279mS PRN: + Slot 4: Base NONE
11:16:31 3541396279mS PRN: + Mezzanine NONE
11:16:31 3541396279mS PRN: +------------------------------------------------------------
11:16:31 3541396279mS PRN: +++++++++++++++++ END OF LIST OF MODULES +++++++++++++++
11:16:31 3541396279mS PRN: +++++++++++++++++ LIST OF MEMORY CARDS ++++++++++++++++++
11:16:31 3541396279mS PRN: +------------------------------------------------------------
11:16:31 3541396279mS PRN: + System SD Card: MNTD
11:16:31 3541396280mS PRN: + CID Register: 0x02544d534430344761b122cd2b00aa1b
11:16:31 3541396280mS PRN: + CSD Register: 0x400e00325b5900001d877f800a400051
11:16:31 3541396280mS PRN: + SCR Register: 0x02b5800026028302
11:16:31 3541396280mS PRN: + OCR Register: 0xc0ff8000
11:16:31 3541396282mS PRN: + Status Register: 0x000000000200000002029004005a
11:16:31 3541396282mS PRN: +------------------------------------------------------------
11:16:31 3541396282mS PRN: + Optional SD Card: UMNT
11:16:31 3541396282mS PRN: +------------------------------------------------------------
11:16:31 3541396282mS PRN: ++++++++++++++ END OF LIST OF MEMORY CARDS +++++++++++++
11:16:31 3541396282mS PRN: ++++++++++++++++++++ MEMORY CAPTURE +++++++++++++++++++++
11:16:31 3541396282mS PRN: +------------------------------------------------------------
11:16:31 3541396282mS PRN: + 0x0000000a, 0x00000000, 0x00000000, 0x000000a9, 0x00000000
11:16:31 3541396282mS PRN: + 0x00000007, 0x00000000, 0x000000a8, 0x00000000, 0x00000000
11:16:31 3541396282mS PRN: + 0x00000000, 0x0000000a, 0x00000000, 0x000000a9, 0x00000000
11:16:31 3541396282mS PRN: + 0x0000000c, 0x00000000, 0x00000000, 0x00000000, 0x00000000
11:16:31 3541396282mS PRN: + 0x00000000, 0x00000000, 0x00000000, 0x00000000, 0x00002890
11:16:31 3541396282mS PRN: + 0x00000000, 0x00000000, 0x00000000, 0x00000000, 0x00000000
11:16:31 3541396283mS PRN: + 0x00000000, 0x00000000, 0x00000000, 0x00000000, 0x00000000
11:16:31 3541396283mS PRN: + 0x00000000, 0x00000000, 0x00000000, 0x00000000, 0x00000000
11:16:31 3541396283mS PRN: + 0x00000000, 0x4f1dd8f8, 0x10f4738c, 0x0a60c56f, 0xd7b6e4e3
11:16:31 3541396283mS PRN: +------------------------------------------------------------
11:16:31 3541396283mS PRN: +++++++++++++++++ END OF MEMORY CAPTURE ++++++++++++++++
11:16:41 3541406124mS H323Evt: Recv: RegistrationRequest 192.168.1.2; Endpoints registered: 3; Endpoints in registration: 0
11:16:46 3541411178mS RES: Mon 30/6/2014 11:16:46 FreeMem=53735056 52848056(1) CachedMem=887000 CMMsg=9(10) Buff=5200 1358 1000 7439 5 Links=12818 BTree=14410 CPU=02.39% CPUStats=1/3/5238/21217/23084/0/1 MCR=0 MCW=0
11:16:46 3541411178mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=66 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=25(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:16:46 3541411178mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:16:49 3541414506mS H323Evt: Recv: RegistrationRequest 192.168.4.196; Endpoints registered: 3; Endpoints in registration: 0
11:16:49 3541414685mS H323Evt: Shared tcp socket for line 18 disconnected
11:16:55 3541420562mS CMExtnEvt: Bench: No user activity
11:17:05 3541430179mS RES: Mon 30/6/2014 11:17:04 FreeMem=53735056 52848056(1) CachedMem=887000 CMMsg=9(10) Buff=5200 1358 1000 7439 5 Links=12818 BTree=14410 CPU=03.19% CPUStats=1/3/5238/21132/23084/0/0 MCR=0 MCW=0
11:17:05 3541430179mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=66 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=25(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:17:05 3541430179mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:17:06 3541431719mS PRN: 125: Digit Pressed 1
11:17:06 3541431720mS CMCallEvt: 0.8021.0 -1 BaseEP: NEW CMEndpoint f4dac078 TOTAL NOW=1 CALL_LIST=0
11:17:06 3541431720mS CMCallEvt: 0.8021.0 -1 Bench.-1: NEW CMExtnEndpoint f4dac078, Name=Bench, Extn=125, Phys Extn=125
11:17:06 3541431721mS CMCallEvt: CREATE CALL:1824 (f4d2bfe0)
11:17:06 3541431721mS CMCallEvt: 0.8022.0 -1 BaseEP: NEW CMEndpoint f4dd7ca8 TOTAL NOW=2 CALL_LIST=0
11:17:06 3541431723mS CMExtnEvt: Bench: CMExtnHandler::SetCurrent( id: 0->8021 )
11:17:06 3541431724mS CMCallEvt: 256.8021.0 1824 Bench.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
11:17:06 3541431724mS CMExtnEvt: v=44 State, new=Dialling old=Idle,0,0,Bench
11:17:06 3541431724mS CMTARGET: 256.8021.0 1824 Bench.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=125 dir=out complete=0 ses=0
11:17:06 3541431724mS CMTARGET: 256.8021.0 1824 Bench.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
11:17:06 3541431725mS CMCallEvt: 256.8021.0 1824 Bench.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
11:17:06 3541431728mS CMExtnTx: v=125, p1=8005
CMFacility
Line: type=IPLine 250 Call: lid=256 id=44 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:17:06 3541431729mS CMExtnTx: v=125, p1=8005
CMFacility
Line: type=IPLine 250 Call: lid=256 id=44 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:17:06 3541431730mS CMExtnTx: v=125, p1=8005
CMFacility
Line: type=IPLine 250 Call: lid=256 id=44 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:17:06 3541431730mS CMTARGET: 256.8021.0 1824 Bench.0: Setting Hard Timer 3000
11:17:06 3541431731mS CMTARGET: 256.8021.0 1824 Bench.0: LOOKUP CALL ROUTE: type=100 called_party=1 sub= calling=125 dir=out complete=0 ses=0
11:17:06 3541431731mS CMTARGET: 256.8021.0 1824 Bench.0: ADD TARGET (N): number=1 type=100 depth=1 nobar=1 setorig=1 ses=0
11:17:06 3541431734mS CD: CALL: 256.8021.0 BState=Idle Cut=0 Music=0.0 Aend="Bench(125)" (0.0) Bend="" [] (0.0) CalledNum=1 () CallingNum=125 (Bench) Internal=1 Time=12 AState=Dialling
11:17:06 3541431735mS H323Evt: SetOperational 1009 192.168.4.199:0 to 0
11:17:08 3541433197mS PRN: 125: Digit Pressed 0
11:17:08 3541433198mS CMTARGET: 256.8021.0 1824 Bench.0: Setting Hard Timer 3000
11:17:08 3541433198mS CMTARGET: 256.8021.0 1824 Bench.0: LOOKUP CALL ROUTE: type=100 called_party=10 sub= calling=125 dir=out complete=0 ses=0
11:17:08 3541433198mS CMTARGET: 256.8021.0 1824 Bench.0: ADD TARGET (N): number=10 type=100 depth=1 nobar=1 setorig=1 ses=0
11:17:08 3541433685mS H323Evt: Shared tcp socket for line 18 disconnected
11:17:09 3541434049mS PRN: 125: Digit Pressed 1
11:17:09 3541434050mS CMTARGET: 256.8021.0 1824 Bench.0: Setting Hard Timer 3000
11:17:09 3541434050mS CMTARGET: 256.8021.0 1824 Bench.0: LOOKUP CALL ROUTE: type=100 called_party=101 sub= calling=125 dir=out complete=0 ses=0
11:17:09 3541434050mS CMTARGET: 256.8021.0 1824 Bench.0: ADD TARGET (N): number=101 type=100 depth=1 nobar=1 setorig=1 ses=0
11:17:09 3541434050mS CMTARGET: 256.8021.0 1824 Bench.0: SET USER: Service orig=1
11:17:09 3541434050mS CMTARGET: 256.8021.0 1824 Bench.0: ADD USER: Service depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeDefault) incl(0x0) excpt(0x0), allow_redir(1) remote=00000000 simult 0 (0)
11:17:09 3541434051mS CMCallEvt: 0.8023.0 -1 BaseEP: NEW CMEndpoint f4cef588 TOTAL NOW=3 CALL_LIST=1
11:17:09 3541434051mS CMCallEvt: 0.8023.0 -1 Service.-1: NEW CMExtnEndpoint f4cef588, Name=Service, Extn=101, Phys Extn=101
11:17:09 3541434052mS CMTARGET: 257.8023.0 1824 Service.0: ADD PRIMARY
11:17:09 3541434052mS CMTARGET: 256.8021.0 1824 Bench.0: CancelTimer CMTCDelayedProcessing
11:17:09 3541434052mS CMTARGET: 256.8021.0 1824 Bench.0: INITIAL TARGETING SUCCEEDED
11:17:09 3541434053mS CMTARGET: 256.8021.0 1824 Bench.0: GetNoAnswerTimer:15
11:17:09 3541434053mS CMCallEvt: 0.8022.0 1824 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
11:17:09 3541434054mS CMCallEvt: 257.8023.0 1824 Service.0: StateChange: END=T CMCSIdle->CMCSOffering
11:17:09 3541434055mS CMExtnEvt: Service: CMExtnHandler::SetCurrent( id: 0->8023 )
11:17:09 3541434056mS CMCallEvt: 257.8023.0 1824 Service.0: StateChange: END=T CMCSOffering->CMCSRinging
11:17:09 3541434056mS CMExtnEvt: v=36 State, new=Ringing old=Idle,0,0,Service
11:17:09 3541434057mS CMCallEvt: 0.8022.0 1824 TargetingEP: StateChange: END=B CMCSOffering->CMCSRinging
11:17:09 3541434057mS CMCallEvt: 256.8021.0 1824 Bench.0: StateChange: END=A CMCSDialling->CMCSRingBack
11:17:09 3541434058mS CMExtnEvt: v=44 State, new=Alerting old=Dialling,0,0,Bench
11:17:09 3541434061mS CD: CALL: 256.8021.0 BState=Ringing Cut=1 Music=2.0 Aend="Bench(125)" (0.0) Bend="Service(101)" [Service(101)] (0.0) CalledNum=101 (Service) CallingNum=125 (Bench) Internal=1 Time=2340 AState=Ringing
11:17:09 3541434063mS CMMap: PCG::AddToneGenerator g R1[3] for cp[259]b0r1 append pcp[261]b0r1 (total 1)
11:17:09 3541434063mS CMMap: PlatformConnectionAudioSAP::Bind pcp[261]b0r1 to 0.0
11:17:09 3541434063mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[261]b0r1 Configure 0.0
11:17:09 3541434063mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[261]b0r1 ConnectIndication 0.0
11:17:09 3541434063mS CMMap: a=0.0 b=0.0 pcp[259]b0r1 RTPR1
11:17:09 3541434064mS H323Evt: SetOperational 1009 192.168.4.199:49152 to 1
11:17:10 3541435085mS H323Evt: RTP(50r): 192.168.4.199/49152 192.168.4.196/51952 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=3350 SENT=51 (avg size=164) RECV=50 (avg size=160)
11:17:11 3541436179mS RES: Mon 30/6/2014 11:17:11 FreeMem=53680240 52848056(1) CachedMem=832184 CMMsg=9(10) Buff=5200 1358 1000 7440 5 Links=12712 BTree=14406 CPU=02.24% CPUStats=1/3/5238/20742/23084/0/0 MCR=0 MCW=0
11:17:11 3541436179mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=72 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=24(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:17:11 3541436180mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:17:11 3541436375mS CMCallEvt: 257.8023.0 1824 Service.0: StateChange: END=T CMCSRinging->CMCSConnReq
11:17:11 3541436375mS CMCallEvt: 0.8022.0 1824 TargetingEP: RequestEnd 257.8023.0 1824 Service.0
11:17:11 3541436376mS CMTARGET: 256.8021.0 1824 Bench.0: CancelTimer CMTCCoverageTimeout
11:17:11 3541436376mS CMCallEvt: 0.8022.0 -1 BaseEP: DELETE CMEndpoint f4dd7ca8 TOTAL NOW=2 CALL_LIST=1
11:17:11 3541436376mS CMExtnEvt: v=36 State, new=Connected old=Ringing,0,0,Service
11:17:11 3541436377mS CMCallEvt: 256.8021.0 1824 Bench.0: StateChange: END=A CMCSRingBack->CMCSOGConnReq
11:17:11 3541436377mS CMExtnEvt: v=44 State, new=Connected old=Alerting,0,0,Bench
11:17:11 3541436384mS CMCallEvt: 256.8021.0 1824 Bench.0: StateChange: END=A CMCSOGConnReq->CMCSConnected
11:17:11 3541436384mS CMTARGET: 256.8021.0 1824 Bench.0: ~CMTargetHandler f4daeed0 ep f4dac078
11:17:11 3541436385mS CMCallEvt: 257.8023.0 1824 Service.0: StateChange: END=B CMCSConnReq->CMCSConnected
11:17:11 3541436387mS CMExtnTx: v=101, p1=8006
CMFacility
Line: type=IPLine 250 Call: lid=257 id=36 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:17:11 3541436389mS CD: CALL: 256.8021.0 BState=Connected Cut=3 Music=0.0 Aend="Bench(125)" (0.0) Bend="Service(101)" [Service(101)] (0.0) CalledNum=101 (Service) CallingNum=125 (Bench) Internal=1 Time=4668 AState=Connected
11:17:11 3541436391mS H323Evt: SetOperational 1010 192.168.4.199:0 to 0
11:17:11 3541436391mS CMMap: PCG::MapBChan pcp[260]b0r1 cp_b 0 other_cp_b 0 type CGTypeSimple
11:17:11 3541436392mS CMMap: a=0.0 b=0.0 pcp[259]b0r1 RTPR0
11:17:11 3541436392mS H323Evt: SetOperational 1009 192.168.4.199:49152 to 0
11:17:11 3541436392mS CMMap: PCG::MapBChan pcp[259]b0r1 cp_b 0 other_cp_b 0 type CGTypeSimple
11:17:11 3541436392mS CMMap: PCG::MapBChan cp RTP local 192.168.4.199:49152 remote 192.168.4.196:51952 , cp_other RTP local: 192.168.4.199:49154 remote 192.168.4.165:51608
11:17:11 3541436392mS CMMap: PCG::MapBChan cp oob 1 rfc_2833 0 , cp_other oob 1, rfc_2833 0, cp behind_nat 0 cp_other behind_nat 0
11:17:11 3541436392mS CMMap: PCG::MapBChan rtpRelay Open got rtpRelay ID: 1
11:17:11 3541436392mS CMMap: PCG::MapBChan rtpRelay Configure success
11:17:11 3541436393mS CMMap: PCG::MapBChan rtpRelay Start success
11:17:11 3541436393mS H323Evt: SetOperational 1009 192.168.4.199:49152 to 1
11:17:11 3541436393mS H323Evt: SetOperational 1010 192.168.4.199:49154 to 1
11:17:15 3541439778mS PRN: Optimizing BTree Lists Completed...Started:3541439535
11:17:18 3541442963mS H323Evt: Recv: RegistrationRequest 192.168.4.165; Endpoints registered: 3; Endpoints in registration: 0
11:17:22 3541446079mS H323Evt: v=0 stacknum=250 State, new=NullState, old=Active id=44
11:17:22 3541446079mS H323Evt: GK: Unregister endpoint VoxVar_53b146e840fc7937 for extension 125 reason 3
11:17:22 3541446079mS CMCallEvt: 256.8021.0 1824 Bench.0: StateChange: END=A CMCSConnected->CMCSCompleted
11:17:22 3541446081mS CMExtnTx: v=101, p1=8006
CMFacility
Line: type=IPLine 250 Call: lid=257 id=36 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:17:22 3541446082mS CMExtnEvt: v=44 State, new=PortRecoverDelay old=Connected,0,0,Bench
11:17:22 3541446083mS CMExtnTx: v=125, p1=8005
CMFacility
Line: type=IPLine 250 Call: lid=256 id=44 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:17:22 3541446084mS CMLOGGING: CALL:2014/06/3011:17,00:00:09,002,125,O,101,101,Bench,,,1,,""n/a,0
11:17:22 3541446085mS CD: CALL: 256.8021.0 BState=Connected Cut=2 Music=0.0 Aend="BService(101)" (0.0) Bend="Service(101)" [Service(101)] (0.0) CalledNum=101 (Service) CallingNum=125 (Bench) Internal=1 Time=14363 AState=Idle
11:17:22 3541446085mS CD: CALL: 256.8021.0 Deleted
11:17:22 3541446085mS CMExtnEvt: Bench: CALL LOST (CMCauseForceClear)
11:17:22 3541446085mS CMExtnEvt: Bench: Extn(125) Calling Party Number(125) Type(CMNTypeInternal)
11:17:22 3541446086mS CMExtnEvt: Bench: CMExtnHandler::SetCurrent( id: 8021->0 )
11:17:22 3541446086mS CMCallEvt: 256.8021.0 -1 Bench.-1: StateChange: END=X CMCSCompleted->CMCSDelete
11:17:22 3541446087mS CMExtnEvt: Service: CALL LOST (CMCauseForceClear)
11:17:22 3541446087mS CMExtnEvt: Service: Extn(101) Calling Party Number(125) Type(CMNTypeInternal)
11:17:22 3541446088mS CMCallEvt: 257.8023.0 -1 Service.0: StateChange: END=X CMCSConnected->CMCSCompleted
11:17:22 3541446088mS CMExtnEvt: v=36 State, new=PortRecoverDelay old=Connected,0,0,Service
11:17:22 3541446088mS CMExtnTx: v=101, p1=8006
CMFacility
Line: type=IPLine 250 Call: lid=257 id=36 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:17:22 3541446089mS CMExtnEvt: Service: CMExtnHandler::SetCurrent( id: 8023->0 )
11:17:22 3541446090mS CMCallEvt: 257.8023.0 -1 Service.-1: StateChange: END=X CMCSCompleted->CMCSDelete
11:17:22 3541446091mS CMCallEvt: 257.8023.0 -1 BaseEP: DELETE CMEndpoint f4cef588 TOTAL NOW=1 CALL_LIST=0
11:17:22 3541446091mS CMCallEvt: END CALL:1824 (f4d2bfe0)
11:17:22 3541446092mS CMCallEvt: 256.8021.0 -1 BaseEP: DELETE CMEndpoint f4dac078 TOTAL NOW=0 CALL_LIST=0
11:17:22 3541446092mS CMExtnEvt: Bench:125 ExtnFault now 1
11:17:22 3541446093mS CMExtnTx: v=125, p1=8005
CMReleaseComp
Line: type=IPLine 250 Call: lid=256 id=44 in=1
Cause=16, Normal call clearing
11:17:22 3541446094mS H323Evt: GK: Send URQ
11:17:22 3541446096mS CMMap: PCG::UnmapBChan pcp[260]b0r1 cp_b 0 other_cp_b 0
11:17:22 3541446096mS H323Evt: SetOperational 1010 192.168.4.199:49154 to 0
11:17:22 3541446096mS H323Evt: SetOperational 1009 192.168.4.199:49152 to 0
11:17:22 3541446096mS CMMap: PCG::UMMapBChan rtpRelay ID: 1 Close success
11:17:22 3541446097mS CMMap: PCG::UnmapBChan pcp[259]b0r1 cp_b 0 other_cp_b 0
11:17:22 3541446097mS H323Evt: RTP(END): 192.168.4.199/49154 192.168.4.165/51608 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=9706 SENT=440 RECV=484 RTdelay=0 jitter=0 loss=0 remotejitter=0 remoteloss=0
11:17:22 3541446098mS H323Evt: RTP(END): 192.168.4.199/49152 192.168.4.196/51952 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=14363 SENT=597 RECV=558 RTdelay=0 jitter=0 loss=0 remotejitter=0 remoteloss=0
11:17:22 3541446202mS RES: Mon 30/6/2014 11:17:21 FreeMem=53765192 52848056(1) CachedMem=917136 CMMsg=9(10) Buff=5200 1359 1000 7439 5 Links=12830 BTree=14411 CPU=01.88% CPUStats=1/3/5238/21073/23084/0/0 MCR=0 MCW=0
11:17:22 3541446202mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=73 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=22(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:17:22 3541446202mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:17:24 3541448086mS CMExtnEvt: Bench: Recover Timer reason=CMTRWrapUp
11:17:24 3541448086mS CMExtnEvt: v=44 State, new=Idle old=PortRecoverDelay,0,0,Bench
11:17:24 3541448090mS CMExtnEvt: Service: Recover Timer reason=CMTRWrapUp
11:17:24 3541448090mS CMExtnEvt: v=36 State, new=Idle old=PortRecoverDelay,0,0,Service
********** SysMonitor v9.0.3.0 build 941 [connected to 192.168.4.199 (VoxVar)] **********
11:17:27 3541451957mS PRN: Monitor Status IP 500 V2 9.0.3.0 build 941
11:17:27 3541451957mS PRN: LAW=U PRI=0, BRI=0, ALOG=4, VCOMP=10, MDM=0, WAN=0, MODU=0 LANM=0 CkSRC=0 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=0(TOT=1824)
11:17:28 3541452686mS H323Evt: Shared tcp socket for line 18 disconnected
11:17:28 3541452703mS RES: Mon 30/6/2014 11:17:28 FreeMem=53765192 52848056(1) CachedMem=917136 CMMsg=9(10) Buff=5200 1358 1000 7440 5 Links=12830 BTree=14411 CPU=02.90% CPUStats=1/3/5238/21112/23084/0/1 MCR=0 MCW=0
11:17:28 3541452704mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=67 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=22(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:17:28 3541452704mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:17:37 3541461155mS H323Evt: Recv: RegistrationRequest 192.168.1.2; Endpoints registered: 2; Endpoints in registration: 0
11:17:43 3541467708mS RES: Mon 30/6/2014 11:17:43 FreeMem=53764040 52848056(1) CachedMem=915984 CMMsg=9(10) Buff=5200 1358 1000 7439 5 Links=12828 BTree=14411 CPU=01.45% CPUStats=1/3/5238/21152/23084/0/1 MCR=0 MCW=0
11:17:43 3541467708mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=66 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=23(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:17:43 3541467708mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:17:47 3541471686mS H323Evt: Shared tcp socket for line 18 disconnected
11:18:02 3541486710mS RES: Mon 30/6/2014 11:18:02 FreeMem=53764040 52848056(1) CachedMem=915984 CMMsg=9(10) Buff=5200 1358 1000 7439 5 Links=12828 BTree=14411 CPU=01.74% CPUStats=1/3/5238/21209/23084/0/0 MCR=0 MCW=0
11:18:02 3541486710mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=66 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=23(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:18:02 3541486710mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:18:06 3541490686mS H323Evt: Shared tcp socket for line 18 disconnected
11:18:12 3541496324mS H323Evt: Recv GRQ from c0a804c4
11:18:12 3541496325mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11:18:12 3541496325mS H323Evt: found number <125>
11:18:12 3541496359mS H323Evt: Recv: RegistrationRequest 192.168.4.196; Endpoints registered: 2; Endpoints in registration: 0
11:18:12 3541496359mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11:18:12 3541496359mS H323Evt: found number <125>
11:18:12 3541496360mS H323Evt: RRQ --- CallSigProtocol is H323AnnexL_P. Go for Avaya 4600IP phone
11:18:12 3541496360mS H323Evt: RRQ --- Register extn 125 using product IP_Phone, version 6.3116
11:18:12 3541496361mS H323Evt: v=(null) stacknum=0 State, new=NullState, old=NullState id=0
11:18:12 3541496464mS H323Evt: v=0 stacknum=250 State, new=NullState, old=NullState id=-1
11:18:12 3541496464mS H323Evt: v=0 stacknum=250 State, new=Present, old=NullState id=45
11:18:12 3541496476mS CMExtnTx: v=125, p1=8005
CMProceeding
Line: type=IPLine 250 Call: lid=256 id=45 in=1
11:18:12 3541496477mS CMExtnTx: v=125, p1=8005
CMConnect
Line: type=IPLine 250 Call: lid=256 id=45 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11:18:12 3541496478mS H323Evt: v=0 stacknum=250 State, new=ICProceeding, old=Present id=45
11:18:12 3541496479mS H323Evt: v=0 stacknum=250 State, new=Active, old=ICProceeding id=45
11:18:12 3541496711mS RES: Mon 30/6/2014 11:18:11 FreeMem=53754992 52848056(1) CachedMem=906936 CMMsg=9(10) Buff=5200 1359 1000 7439 5 Links=12824 BTree=14411 CPU=05.15% CPUStats=12/21/5238/20641/23084/0/0 MCR=0 MCW=0
11:18:12 3541496711mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=70 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=0 TCP=24(TLS=4) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:18:12 3541496711mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
11:18:13 3541497973mS H323Evt: Recv: RegistrationRequest 192.168.4.165; Endpoints registered: 2; Endpoints in registration: 1
11:18:15 3541499487mS CMExtnTx: v=125, p1=8005
CMInformation
Line: type=IPLine 250 Call: lid=256 id=45 in=1
IE (13) unknown
11:18:15 3541499489mS CMExtnEvt: Bench:125 ExtnFault now 0
11:18:15 3541499491mS CMExtnEvt: 125 ReportAttachment type=0
11:18:15 3541499495mS PRN: Config Write Wake Up
11:18:15 3541499995mS PRN: Updates IO list size 1 updated list size 1