UNICODE-UTF8 enu 10:48:17 2987955727mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=96 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:48:17 2987955727mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:48:17 2987955727mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:48:17 2987955773mS H323Evt: Recv: RegistrationRequest 192.168.252.133; Extn(495), time since last RRQ-KA 55040, Endpoints registered: 13; Endpoints in registration: 0 ********** Warning: Logging to Screen Started ********** 10:48:20 2987959631mS H323Evt: Recv: RegistrationRequest 192.168.252.132; Extn(601), time since last RRQ-KA 55043, Endpoints registered: 13; Endpoints in registration: 0 10:48:23 2987962330mS CMExtnEvt: mstevenson: No user activity 10:48:23 2987962594mS H323Evt: Recv: RegistrationRequest 192.168.1.105; Extn(253), time since last RRQ-KA 55011, Endpoints registered: 13; Endpoints in registration: 0 10:48:26 2987964230mS H323Evt: Recv: RegistrationRequest 192.168.1.102; Extn(250), time since last RRQ-KA 55012, Endpoints registered: 13; Endpoints in registration: 0 10:48:27 2987965064mS CMCallEvt: 0000000000000000 0.688287.0 -1 BaseEP: NEW CMEndpoint f48686dc TOTAL NOW=3 CALL_LIST=1 10:48:27 2987965064mS CMCallEvt: 0000000000000000 0.688287.0 -1 jpulaskey.-1: NEW CMExtnEndpoint f48686dc, Name=jpulaskey, Extn=219, Phys Extn=219 10:48:27 2987965064mS CMCallEvt: CREATE CALL:188900 (f16720f4) 10:48:27 2987965064mS CMCallEvt: 0000000000000000 0.688288.0 -1 BaseEP: NEW CMEndpoint f171e7e8 TOTAL NOW=4 CALL_LIST=1 10:48:27 2987965067mS CMExtnEvt: jpulaskey: CMExtnHandler::SetCurrent( id: 0->688287 ) 10:48:27 2987965067mS CMCallEvt: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: StateChange: END=A CMCSIdle->CMCSDialInitiated 10:48:27 2987965067mS CMExtnEvt: v=6 State, new=Dialling old=Idle,0,0,jpulaskey 10:48:27 2987965068mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party= sub= calling=219 calling_sub= dir=out complete=0 ses=0 10:48:27 2987965068mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:27 2987965069mS CMCallEvt: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: StateChange: END=A CMCSDialInitiated->CMCSDialling 10:48:27 2987965071mS CD: CALL: 0.688287.0 BState=Idle Cut=1 Music=3.0 Aend="jpulaskey(219)" (8.8) Bend="" [] (0.0) CalledNum= () CallingNum=219 (jpulaskey) Internal=1 Time=7 AState=DialInitiated 10:48:27 2987965073mS CMMap: a=8.8 b=0.0 D1 10:48:27 2987965213mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,219: Digit Key Pressed 2 10:48:27 2987965213mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: Setting Hard Timer 4000 10:48:27 2987965214mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=2 sub= calling=219 calling_sub= dir=out complete=0 ses=0 10:48:27 2987965214mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: ADD TARGET (N): number=2 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:27 2987965216mS CMMap: a=8.8 b=0.0 D0 10:48:27 2987965232mS RES: Fri 22/9/2017 10:48:27 FreeMem=47657116 Heap=45506708(3) Cache=2150408 MemObjs=33999(36418) CMMsg=8(9) ASN=0 Buff=5200 1356 999 7362 5 Links=85081(85971) BTree=3411(6946) CPU=17.61% CPUStats=18.69%/10/16/144/12022/15010/00.14%/ 0/02.80% MCR=0 MCW=0 10:48:27 2987965232mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=99 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:48:27 2987965232mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:48:27 2987965232mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:48:27 2987965423mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,219: Digit Key Pressed 2 10:48:27 2987965424mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: Setting Hard Timer 4000 10:48:27 2987965424mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=22 sub= calling=219 calling_sub= dir=out complete=0 ses=0 10:48:27 2987965425mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: ADD TARGET (N): number=22 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:27 2987965630mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,219: Digit Key Pressed 6 10:48:27 2987965630mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: Setting Hard Timer 4000 10:48:27 2987965631mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=226 sub= calling=219 calling_sub= dir=out complete=0 ses=0 10:48:27 2987965631mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: ADD TARGET (N): number=226 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:27 2987965631mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: SET USER: dford orig=1 10:48:27 2987965631mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: ADD USER: dford 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) 10:48:27 2987965632mS CMCallEvt: 0000000000000000 0.688289.0 -1 BaseEP: NEW CMEndpoint f4872060 TOTAL NOW=5 CALL_LIST=2 10:48:27 2987965632mS CMCallEvt: 0000000000000000 0.688289.0 -1 dford.-1: NEW CMExtnEndpoint f4872060, Name=dford, Extn=226, Phys Extn=226 10:48:27 2987965633mS CMTARGET: c0a8000a000a80a1 0.688289.0 188900 dford.0: ADD PRIMARY 10:48:27 2987965633mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: CancelTimer CMTCDelayedProcessing 10:48:27 2987965634mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: INITIAL TARGETING SUCCEEDED 10:48:27 2987965634mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: GetNoAnswerTimer:15 10:48:27 2987965634mS CMCallEvt: 0000000000000000 0.688288.0 188900 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering 10:48:27 2987965635mS CMCallEvt: c0a8000a000a80a1 0.688289.0 188900 dford.0: StateChange: END=T CMCSIdle->CMCSOffering 10:48:27 2987965635mS CMExtnEvt: dford: CMExtnHandler::SetCurrent( id: 0->688289 ) 10:48:27 2987965636mS CMCallEvt: c0a8000a000a80a1 0.688289.0 188900 dford.0: StateChange: END=T CMCSOffering->CMCSRinging 10:48:27 2987965636mS CMExtnEvt: v=13 State, new=Ringing old=Idle,0,0,dford 10:48:27 2987965637mS CMCallEvt: 0000000000000000 0.688288.0 188900 TargetingEP: StateChange: END=B CMCSOffering->CMCSRinging 10:48:27 2987965637mS CMCallEvt: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: StateChange: END=A CMCSDialling->CMCSRingBack 10:48:27 2987965638mS CMExtnEvt: v=6 State, new=Alerting old=Dialling,0,0,jpulaskey 10:48:27 2987965639mS CD: CALL: 0.688287.0 BState=Ringing Cut=1 Music=2.0 Aend="jpulaskey(219)" (8.8) Bend="dford(226)" [dford(226)] (0.0) CalledNum=226 (dford) CallingNum=219 (jpulaskey) Internal=1 Time=575 AState=Ringing 10:48:27 2987965641mS CMMap: a=8.8 b=0.0 R1 10:48:29 2987967207mS H323Evt: Recv: RegistrationRequest 192.168.1.104; Extn(252), time since last RRQ-KA 55015, Endpoints registered: 13; Endpoints in registration: 0 10:48:30 2987968413mS H323Evt: Recv: RegistrationRequest 192.168.1.106; Extn(254), time since last RRQ-KA 55016, Endpoints registered: 13; Endpoints in registration: 0 10:48:32 2987970328mS H323Evt: Recv: RegistrationRequest 192.168.1.103; Extn(251), time since last RRQ-KA 55011, Endpoints registered: 13; Endpoints in registration: 0 10:48:35 2987973103mS PRN: Optimizing BTree Lists Completed...Started:2987973102 Duration:1 Size:383 Attempted:383 10:48:37 2987975634mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: TimerExpired cause=CMTCCoverageTimeout 10:48:37 2987975634mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: GetNoAnswerTimer:15 10:48:40 2987978791mS CMCallEvt: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: StateChange: END=A CMCSRingBack->CMCSCompleted 10:48:40 2987978791mS CMTARGET: c0a8000a000a809f 0.688287.0 188900 jpulaskey.0: CancelTimer CMTCNoAnswerTimeout 10:48:40 2987978791mS CMExtnEvt: v=6 State, new=PortRecoverDelay old=Alerting,0,0,jpulaskey 10:48:40 2987978793mS CMLOGGING: CALL:2017/09/2210:48,00:00:00,013,219,O,226,226,jpulaskey,,,1,,"",0,n/a 10:48:40 2987978793mS CD: CALL: 0.688287.0 BState=Ringing Cut=0 Music=0.0 Aend="jpulaskey(219)" (8.8) Bend="dford(226)" [dford(226)] (0.0) CalledNum=226 (dford) CallingNum=219 (jpulaskey) Internal=1 Time=13729 AState=Idle 10:48:40 2987978793mS CD: CALL: 0.688287.0 Deleted 10:48:40 2987978794mS CMExtnEvt: jpulaskey: CALL LOST (CMCauseNormal) 10:48:40 2987978794mS CMExtnEvt: jpulaskey: Extn(219) Calling Party Number(219) Type(CMNTypeInternal) 10:48:40 2987978794mS CMExtnEvt: jpulaskey: CMExtnHandler::SetCurrent( id: 688287->0 ) 10:48:40 2987978794mS CMCallEvt: c0a8000a000a809f 0.688287.0 -1 jpulaskey.-1: StateChange: END=X CMCSCompleted->CMCSDelete 10:48:40 2987978795mS CMCallEvt: 0000000000000000 0.688288.0 -1 BaseEP: DELETE CMEndpoint f171e7e8 TOTAL NOW=4 CALL_LIST=1 10:48:40 2987978795mS CMExtnEvt: dford: CALL LOST (CMCauseNormal) 10:48:40 2987978796mS CMExtnEvt: dford: Extn(226) Calling Party Number(219) Type(CMNTypeInternal) 10:48:40 2987978796mS CMCallEvt: c0a8000a000a80a1 0.688289.0 -1 dford.0: StateChange: END=X CMCSRinging->CMCSCompleted 10:48:40 2987978796mS CMExtnEvt: v=13 State, new=PortRecoverDelay old=Ringing,0,0,dford 10:48:40 2987978797mS CMExtnEvt: dford: CMExtnHandler::SetCurrent( id: 688289->0 ) 10:48:40 2987978798mS CMCallEvt: c0a8000a000a80a1 0.688289.0 -1 dford.-1: StateChange: END=X CMCSCompleted->CMCSDelete 10:48:40 2987978798mS CMCallEvt: c0a8000a000a80a1 0.688289.0 -1 BaseEP: DELETE CMEndpoint f4872060 TOTAL NOW=3 CALL_LIST=1 10:48:40 2987978798mS CMCallEvt: END CALL:188900 (f16720f4) 10:48:40 2987978799mS CMTARGET: c0a8000a000a809f 0.688287.0 -1 BaseEP: ~CMTargetHandler f1749e0c ep f48686dc 10:48:40 2987978799mS CMCallEvt: c0a8000a000a809f 0.688287.0 -1 BaseEP: DELETE CMEndpoint f48686dc TOTAL NOW=2 CALL_LIST=1 10:48:40 2987978802mS PRN: Config Write Wake Up 10:48:40 2987978802mS CMMap: a=8.8 b=0.0 R0 10:48:40 2987978808mS CMExtnEvt: dford: Recover Timer reason=CMTRWrapUp 10:48:40 2987978808mS CMExtnEvt: v=13 State, new=Idle old=PortRecoverDelay,0,0,dford 10:48:41 2987979177mS RES: Fri 22/9/2017 10:48:40 FreeMem=47683936 Heap=45506708(3) Cache=2177228 MemObjs=33976(36418) CMMsg=8(9) ASN=0 Buff=5200 1357 1000 7363 5 Links=85076(85971) BTree=3401(6946) CPU=18.31% CPUStats=18.50%/11/17/144/11820/15010/00.14% /1/02.77% MCR=0 MCW=0 10:48:41 2987979177mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=100 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:48:41 2987979177mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:48:41 2987979178mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:48:41 2987979303mS PRN: Updates IO list size 1 updated list size 1 10:48:41 2987979303mS PRN: Sending Updates out to f497c45c started 10:48:41 2987979304mS PRN: Sending Updates out to f497c45c finished 10:48:41 2987979304mS PRN: Config Write Completed 10:48:41 2987980527mS PRN: Created WAV file MOH Source 1 10:48:41 2987980795mS CMExtnEvt: jpulaskey: Recover Timer reason=CMTRWrapUp 10:48:41 2987980795mS CMExtnEvt: v=6 State, new=Idle old=PortRecoverDelay,0,0,jpulaskey 10:48:41 2987980875mS PRN: Loading HoldMusic.wav from ipaddr=255.255.255.255 10:48:42 2987981124mS PRN: WAV Hold Music HoldMusic.wav failed to load 10:48:42 2987981124mS PRN: Deleted WAV file MOH Source 1 10:48:42 2987981124mS PRN: Created Tone MOH Source 1 10:48:42 2987981124mS PRN: Stopped tone MOH Source 1 10:48:42 2987981124mS PRN: Deleted Tone MOH Source 1 10:48:42 2987981125mS PRN: Playing tone MOH Source 1 10:48:52 2987991113mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 5 10:48:52 2987991115mS CMCallEvt: 0000000000000000 0.688290.0 -1 BaseEP: NEW CMEndpoint f48686dc TOTAL NOW=3 CALL_LIST=1 10:48:52 2987991115mS CMCallEvt: 0000000000000000 0.688290.0 -1 jessenmacher.-1: NEW CMExtnEndpoint f48686dc, Name=jessenmacher, Extn=361, Phys Extn=361 10:48:52 2987991116mS CMCallEvt: CREATE CALL:188901 (f16720f4) 10:48:52 2987991116mS CMCallEvt: 0000000000000000 0.688291.0 -1 BaseEP: NEW CMEndpoint f171e7e8 TOTAL NOW=4 CALL_LIST=1 10:48:52 2987991118mS CMExtnEvt: jessenmacher: CMExtnHandler::SetCurrent( id: 0->688290 ) 10:48:52 2987991119mS CMCallEvt: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: StateChange: END=A CMCSIdle->CMCSDialInitiated 10:48:52 2987991119mS CMExtnEvt: v=12 State, new=Dialling old=Idle,0,0,jessenmacher 10:48:52 2987991120mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party= sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:52 2987991120mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:52 2987991120mS CMCallEvt: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: StateChange: END=A CMCSDialInitiated->CMCSDialling 10:48:52 2987991121mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:52 2987991122mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=5 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:52 2987991122mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=5 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:52 2987991123mS CD: CALL: 0.688290.0 BState=Idle Cut=0 Music=0.0 Aend="jessenmacher(361)" (10.14) Bend="" [] (0.0) CalledNum=5 () CallingNum=361 (jessenmacher) Internal=1 Time=7 AState=Dialling 10:48:52 2987991189mS RES: Fri 22/9/2017 10:48:53 FreeMem=47657120 Heap=45506708(3) Cache=2150412 MemObjs=33999(36418) CMMsg=8(9) ASN=0 Buff=5200 1355 1000 7363 5 Links=85077(85971) BTree=3404(6946) CPU=18.37% CPUStats=18.79%/11/18/144/11941/15010/00.12% /1/02.77% MCR=0 MCW=0 10:48:52 2987991190mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=108 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:48:52 2987991190mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:48:52 2987991190mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:48:52 2987991442mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 1 10:48:52 2987991443mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:52 2987991443mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=51 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:52 2987991443mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=51 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:52 2987991787mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 2 10:48:52 2987991787mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:52 2987991788mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:52 2987991788mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=512 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:53 2987992035mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 4 10:48:53 2987992036mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:53 2987992036mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=5124 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:53 2987992036mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=5124 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:53 2987992315mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 8 10:48:53 2987992316mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:53 2987992316mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=51248 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:53 2987992316mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=51248 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:53 2987992579mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 6 10:48:53 2987992580mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:53 2987992580mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512486 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:53 2987992580mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=512486 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:53 2987992843mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 2 10:48:53 2987992844mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:53 2987992844mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=5124862 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:53 2987992844mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=5124862 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:54 2987993219mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 8 10:48:54 2987993220mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:54 2987993220mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=51248628 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:54 2987993220mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=51248628 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:57 2987995353mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 2 10:48:57 2987995354mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:57 2987995354mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512486282 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:57 2987995354mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=512486282 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:57 2987995600mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 5 10:48:57 2987995601mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:57 2987995601mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=5124862825 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:57 2987995601mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=5124862825 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:57 2987995867mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 6 10:48:57 2987995868mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:57 2987995868mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=51248628256 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:57 2987995868mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=51248628256 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:58 2987996126mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 1 10:48:58 2987996126mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: Setting Hard Timer 4000 10:48:58 2987996127mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512486282561 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:48:58 2987996127mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=512486282561 type=100 depth=1 nobar=1 setorig=1 ses=0 10:48:58 2987996194mS RES: Fri 22/9/2017 10:48:57 FreeMem=47657032 Heap=45506708(3) Cache=2150324 MemObjs=34001(36418) CMMsg=8(9) ASN=0 Buff=5200 1355 999 7362 5 Links=85077(85971) BTree=3404(6946) CPU=18.13% CPUStats=18.40%/2/8/144/11870/15010/00.24%/1/ 02.86% MCR=0 MCW=0 10:48:58 2987996195mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=98 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:48:58 2987996195mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:48:58 2987996195mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:49:00 2987998863mS CMExtnEvt: bwisenbaugh: No user activity 10:49:02 2988000126mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: TimerExpired cause=CMTCDelayedProcessing 10:49:02 2988000126mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512486282561 sub= calling=361 calling_sub= dir=out complete=1 ses=0 10:49:02 2988000126mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: ADD TARGET (N): number=512486282561 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:02 2988000127mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: USER SC: 512486282561 3 12486282561 sc=type=Dial code=5N;, num=Ns9892698242 10:49:02 2988000127mS CMARS: FindActiveARSByGroupID GroupID=0 - Not Found 10:49:02 2988000127mS CMLRQ: FindActiveLRQByGroupID GroupID=0 - Not Found 10:49:02 2988000128mS CMCallEvt: 0000000000000000 0.688292.0 -1 BaseEP: NEW CMEndpoint f173e278 TOTAL NOW=5 CALL_LIST=2 10:49:02 2988000128mS CMTARGET: ISDN BChannel 23: in-service check = 1 10:49:02 2988000129mS CMTARGET: ISDN BChannel 23: in-service check = 1 10:49:02 2988000130mS CMTARGET: DIAL LINE: 188901 GROUP = 0 SUCCESS = f173e278 10:49:02 2988000131mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: INITIAL TARGETING SUCCEEDED 10:49:02 2988000131mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: GetNoAnswerTimer:15 10:49:02 2988000131mS CMCallEvt: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: StateChange: END=A CMCSDialling->CMCSDialled 10:49:02 2988000131mS CMExtnEvt: v=12 State, new=Proceeding old=Dialling,0,0,jessenmacher 10:49:02 2988000132mS CMCallEvt: 0000000000000000 0.688291.0 188901 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering 10:49:02 2988000132mS CMCallEvt: c0a8000a000a80a4 0.688292.0 188901 Q931 Trunk:6 CHAN=23: StateChange: END=T CMCSIdle->CMCSOffering 10:49:02 2988000133mS PRN: Setting configured voice gain for ch 23. 10:49:02 2988000133mS CMLineTx: v=6 CMSetup Line: type=Q931Line 6 Call: lid=0 id=688292 in=0 Called[12486282561] Type=National (2) Reason=CMDRdirect Calling[9892698242] Type=National Plan=ISDN BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw BChan: slot=0 chan=23 Timed: 22/09/17 10:49 Locale: enu 10:49:02 2988000133mS CD: CALL: 0.688290.0 BState=Idle Cut=1 Music=0.0 Aend="jessenmacher(361)" (10.14) Bend="Line 6" [Line 6] (0.0) CalledNum=512486282561 () CallingNum=361 (jessenmacher) Internal=0 Time=9017 AState=Dialled 10:49:02 2988000135mS ISDNL3Evt: v=6 stacknum=6 State, new=Initiated, old=NullState id=688292 10:49:02 2988000158mS ISDNL3Evt: v=6 stacknum=6 State, new=Proceeding, old=Initiated id=688292 10:49:02 2988000159mS CMLineRx: v=6 CMProceeding Line: type=Q931Line 6 Call: lid=0 id=688292 in=0 BChan: slot=0 chan=23 10:49:02 2988000159mS CMCallEvt: 0000000000000000 0.688291.0 188901 TargetingEP: RequestEnd c0a8000a000a80a4 0.688292.0 188901 Q931 Trunk:6 CHAN=23 10:49:02 2988000159mS CMTARGET: c0a8000a000a80a2 0.688290.0 188901 jessenmacher.0: CancelTimer CMTCNoAnswerTimeout 10:49:02 2988000159mS CMCallEvt: 0000000000000000 0.688291.0 -1 BaseEP: DELETE CMEndpoint f171e7e8 TOTAL NOW=4 CALL_LIST=2 10:49:02 2988000160mS CMCallEvt: c0a8000a000a80a4 0.688292.0 188901 Q931 Trunk:6 CHAN=23: StateChange: END=B CMCSOffering->CMCSAccept 10:49:02 2988000161mS CD: CALL: 0.688290.0 BState=Ringing Cut=3 Music=0.0 Aend="jessenmacher(361)" (10.14) Bend="Line 6" [Line 6] (3.56) CalledNum=12486282561 () CallingNum=361 (jessenmacher) Internal=0 Time=9045 AState=Dialled 10:49:02 2988000162mS CMMap: PCG::MapBChan pcp[191]b1r0 cp_b f4a5f998 other_cp_b 0 type CGTypeSimple 10:49:02 2988000162mS CMMap: PCG::MapBChan pcp[117]b1r0 cp_b f5211db4 other_cp_b f4a5f998 type CGTypeSimple 10:49:02 2988000162mS CMMap: a=10.14 b=3.56 M12 10:49:02 2988000211mS CMExtnEvt: lshaw: No user activity 10:49:03 2988001483mS H323Evt: Recv: RegistrationRequest 192.168.252.134; Extn(604), time since last RRQ-KA 55041, Endpoints registered: 13; Endpoints in registration: 0 10:49:04 2988002088mS H323Evt: Recv: RegistrationRequest 192.168.252.139; Extn(612), time since last RRQ-KA 55045, Endpoints registered: 13; Endpoints in registration: 0 ********** SysMonitor v9.1.6.0 build 153 [connected to 192.168.0.10 (Huron County)] ********** 10:49:06 2988004313mS PRN: Monitor Status IP 500 V2 9.1.6.0 build 153 10:49:06 2988004313mS PRN: LAW=U PRI=2, BRI=0, ALOG=4, VCOMP=10, MDM=0, WAN=0, MODU=5 LANM=0 CkSRC=5 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=2(TOT=188901) 10:49:09 2988007478mS H323Evt: Recv: RegistrationRequest 192.168.252.136; Extn(606), time since last RRQ-KA 55045, Endpoints registered: 13; Endpoints in registration: 0 10:49:09 2988007692mS H323Evt: Recv: RegistrationRequest 192.168.252.138; Extn(611), time since last RRQ-KA 55046, Endpoints registered: 13; Endpoints in registration: 0 10:49:09 2988007754mS H323Evt: Recv: RegistrationRequest 192.168.252.135; Extn(605), time since last RRQ-KA 55056, Endpoints registered: 13; Endpoints in registration: 0 10:49:11 2988009146mS CMExtnEvt: mrowe: No user activity 10:49:11 2988009401mS H323Evt: Recv: RegistrationRequest 192.168.252.137; Extn(609), time since last RRQ-KA 55046, Endpoints registered: 13; Endpoints in registration: 0 10:49:11 2988009564mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:11 2988009564mS ISDNL3Evt: v=6 stacknum=6 State, new=Present, old=NullState id=24 10:49:11 2988009565mS CMLineRx: v=6 CMSetup Line: type=Q931Line 6 Call: lid=6 id=24 in=1 Called[912486282561] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[519892698242] Type=Unknown Plan=ISDN Pres=Allowed (0) BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw BChan: slot=0 chan=1 10:49:11 2988009565mS PRN: Q931Trunk: Found QBChannel to match 0.1 --> 3.34 10:49:11 2988009566mS CMCallEvt: 0000000000000000 0.688293.0 -1 BaseEP: NEW CMEndpoint f16c5094 TOTAL NOW=5 CALL_LIST=2 10:49:11 2988009566mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:11 2988009566mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:11 2988009567mS CMCallEvt: CREATE CALL:188902 (f1740e5c) 10:49:11 2988009567mS CMCallEvt: 0000000000000000 0.688294.0 -1 BaseEP: NEW CMEndpoint f171e7e8 TOTAL NOW=6 CALL_LIST=2 10:49:11 2988009570mS CD: CALL: 6.24.1 BState=Idle Cut=1 Music=0.0 Aend="Line 6" (3.34) Bend="" [] (0.0) CalledNum=912486282561 () CallingNum=519892698242 () Internal=0 Time=3 AState=Idle 10:49:11 2988009570mS CMCallEvt: c0a8000a00000018 6.24.1 188902 Q931 Trunk:6 CHAN=1: StateChange: END=A CMCSIdle->CMCSDialInitiated 10:49:11 2988009570mS CMTARGET: c0a8000a00000018 6.24.1 188902 Q931 Trunk:6 CHAN=1: LOOKUP CALL ROUTE: GID=0 type=0 called_party=912486282561 sub= calling=519892698242 calling_sub= dir=in complete=1 ses=0 10:49:11 2988009572mS CMLOGGING: CALL:2017/09/2210:49,00:00:00,000,519892698242,I,912486282561,912486282561,,,,0,,"",0,n/a 10:49:11 2988009573mS CD: CALL: 6.24.1 BState=Idle Cut=0 Music=0.0 Aend="Line 6" (3.34) Bend="" [] (0.0) CalledNum=912486282561 () CallingNum=519892698242 () Internal=0 Time=6 AState=Dialling 10:49:11 2988009573mS CD: CALL: 6.24.1 Deleted 10:49:11 2988009573mS CMLineTx: v=6 CMReleaseComp Line: type=Q931Line 6 Call: lid=6 id=24 in=1 Cause=88, Incompatible destination 10:49:11 2988009573mS CMCallEvt: c0a8000a00000018 6.24.1 -1 Q931 Trunk:6 CHAN=1: StateChange: END=X CMCSDialInitiated->CMCSDelete 10:49:11 2988009573mS CMCallEvt: 0000000000000000 0.688294.0 -1 BaseEP: DELETE CMEndpoint f171e7e8 TOTAL NOW=5 CALL_LIST=2 10:49:11 2988009574mS CMCallEvt: END CALL:188902 (f1740e5c) 10:49:11 2988009574mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:11 2988009575mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:11 2988009575mS CMTARGET: c0a8000a00000018 6.24.1 -1 BaseEP: ~CMTargetHandler f16a7e80 ep f16c5094 10:49:11 2988009575mS CMCallEvt: c0a8000a00000018 6.24.1 -1 BaseEP: DELETE CMEndpoint f16c5094 TOTAL NOW=4 CALL_LIST=2 10:49:11 2988009577mS ISDNL3Evt: v=6 stacknum=6 State, new=NullState, old=Present id=24 10:49:11 2988009590mS ISDNL3Evt: v=6 stacknum=6 State, new=ReleaseReq, old=Proceeding id=688292 10:49:11 2988009597mS ISDNL3Evt: v=6 stacknum=6 State, new=NullState, old=ReleaseReq id=688292 10:49:11 2988009598mS CMLineRx: v=6 CMReleaseComp Line: type=Q931Line 6 Call: lid=0 id=688292 in=0 BChan: slot=0 chan=23 Cause=88, Incompatible destination 10:49:11 2988009598mS CMCallEvt: c0a8000a000a80a4 0.688292.0 188901 Q931 Trunk:6 CHAN=23: StateChange: END=B CMCSAccept->CMCSCompleted 10:49:11 2988009600mS CMLOGGING: CALL:2017/09/2210:48,00:00:00,000,361,O,12486282561,512486282561,jessenmacher,,,0,,"",0,n/a 10:49:11 2988009600mS CD: CALL: 0.688290.0 BState=Disconnecting Cut=1 Music=0.0 Aend="jessenmacher(361)" (10.14) Bend="Line 6" [Line 6] (3.56) CalledNum=12486282561 () CallingNum=361 (jessenmacher) Internal=0 Time=18484 AState=Dialled 10:49:11 2988009600mS CD: CALL: 0.688290.0 Deleted 10:49:11 2988009601mS CMExtnEvt: jessenmacher: CALL LOST (CMCauseIncompatible) 10:49:11 2988009601mS CMExtnEvt: jessenmacher: Extn(361) Calling Party Number(361) Type(CMNTypeInternal) 10:49:11 2988009602mS CMCallEvt: c0a8000a000a80a2 0.688290.0 -1 jessenmacher.0: StateChange: END=X CMCSDialled->CMCSCompletedTone 10:49:11 2988009602mS CMExtnEvt: v=12 State, new=CMESCompleted old=Proceeding,0,0,jessenmacher 10:49:11 2988009603mS CMCallEvt: c0a8000a000a80a4 0.688292.0 -1 Q931 Trunk:6 CHAN=23: StateChange: END=X CMCSCompleted->CMCSDelete 10:49:11 2988009603mS CMCallEvt: END CALL:188901 (f16720f4) 10:49:11 2988009604mS CMTARGET: ISDN BChannel 23: in-service check = 1 10:49:11 2988009604mS CMTARGET: ISDN BChannel 23: in-service check = 1 10:49:11 2988009604mS CMCallEvt: c0a8000a000a80a4 0.688292.0 -1 BaseEP: DELETE CMEndpoint f173e278 TOTAL NOW=3 CALL_LIST=1 10:49:11 2988009606mS CMMap: PCG::UnmapBChan pcp[191]b1r0 cp_b f4a5f998 other_cp_b f5211db4 10:49:11 2988009606mS CMMap: a=3.56 b=10.14 M02 10:49:11 2988009606mS CMMap: PCG::UnmapBChan pcp[117]b1r0 cp_b f5211db4 other_cp_b 0 10:49:11 2988009607mS CMMap: a=21.11 b=0.0 DTMF::AllocateRAS allocated CMRTVoicemail(f5397878) resource busy 2, total 45 10:49:11 2988009607mS CMMap: a=21.11 b=1.65535 T 10:49:11 2988009607mS CMMap: a=21.11 b=10.14 M22 10:49:11 2988009711mS RES: Fri 22/9/2017 10:49:11 FreeMem=47669432 Heap=45506708(3) Cache=2162724 MemObjs=33980(36418) CMMsg=8(9) ASN=0 Buff=5200 1339 997 7361 5 Links=85094(85971) BTree=3405(6946) CPU=17.47% CPUStats=16.65%/1/4/144/12242/15010/00.07%/0/ 02.76% MCR=0 MCW=0 10:49:11 2988009711mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=99 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:49:11 2988009711mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:49:11 2988009711mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:49:12 2988010698mS SIP Rx: UDP 192.168.1.108:5060 -> 10.1.0.21:5060 OPTIONS sip:9892693555@192.168.1.108 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.108:5060;branch=z9hG4bKac804782064 Max-Forwards: 70 From: ;tag=1c804755509 To: Call-ID: 8047515532292017204923@192.168.1.108 CSeq: 1 OPTIONS Contact: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: MP-124E FXS/v.6.60A.332.002 Accept: application/sdp, application/simple-message-summary, message/sipfrag Content-Length: 0 10:49:12 2988010703mS SIP Tx: UDP 10.1.0.21:5060 -> 192.168.1.108:5060 SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.108:5060;branch=z9hG4bKac804782064 From: ;tag=1c804755509 Call-ID: 8047515532292017204923@192.168.1.108 CSeq: 1 OPTIONS Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,NOTIFY,UPDATE Supported: timer Server: IP Office 9.1.6.0 build 153 To: ;tag=d95b335a819d7127 Content-Type: application/sdp Content-Length: 233 v=0 o=UserA 1171442705 1549991683 IN IP4 0.0.0.0 s=Session SDP c=IN IP4 0.0.0.0 t=0 0 m=audio 8000 RTP/AVP 0 8 18 4 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:4 G723/16000 10:49:12 2988010818mS H323Evt: Recv: RegistrationRequest 192.168.252.133; Extn(495), time since last RRQ-KA 55045, Endpoints registered: 13; Endpoints in registration: 0 10:49:13 2988011430mS CMCallEvt: c0a8000a000a8097 0.688279.0 188894 mstevenson.0: StateChange: END=B CMCSConnected->CMCSCompleted 10:49:13 2988011430mS CMExtnEvt: v=13 State, new=PortRecoverDelay old=Connected,0,0,mstevenson 10:49:13 2988011432mS CMLOGGING: CALL:2017/09/2210:46,00:02:04,010,512319942063,I,723,9892699269,PEDALINGBEANS,,,0,,"",0,n/a 10:49:13 2988011432mS CD: CALL: 5.10.1 BState=Disconnecting Cut=1 Music=0.0 Aend="Line 5" (3.2) Bend="" [mstevenson(418)] (11.15) CalledNum=418 (mstevenson) CallingNum=512319942063 (PEDALING BEANS) Internal=0 Time=134929 AState=Connected 10:49:13 2988011432mS CD: CALL: 5.10.1 Deleted 10:49:13 2988011433mS CMLineTx: v=5 CMDisconnect Line: type=Q931Line 5 Call: lid=5 id=10 in=1 Cause=16, Normal call clearing 10:49:13 2988011434mS CMCallEvt: c0a8000a0000000a 5.10.1 -1 Q931 Trunk:5 CHAN=1: StateChange: END=X CMCSConnected->CMCSCompleted 10:49:13 2988011434mS CMExtnEvt: mstevenson: CALL LOST (CMCauseNormal) 10:49:13 2988011434mS CMExtnEvt: mstevenson: Extn(418) Calling Party Number(418) Type(CMNTypeInternal) 10:49:13 2988011434mS CMExtnEvt: mstevenson: CMExtnHandler::SetCurrent( id: 688279->0 ) 10:49:13 2988011435mS CMCallEvt: c0a8000a000a8097 0.688279.0 -1 mstevenson.-1: StateChange: END=X CMCSCompleted->CMCSDelete 10:49:13 2988011435mS CMCallEvt: END CALL:188894 (f162ca00) 10:49:13 2988011435mS CMCallEvt: c0a8000a000a8097 0.688279.0 -1 BaseEP: DELETE CMEndpoint f47e08cc TOTAL NOW=2 CALL_LIST=0 10:49:13 2988011439mS CMMap: PCG::UnmapBChan pcp[72]b1r0 cp_b f5351fd8 other_cp_b f4a3f324 10:49:13 2988011439mS CMMap: a=11.15 b=3.2 M02 10:49:13 2988011439mS CMMap: PCG::UnmapBChan pcp[198]b1r0 cp_b f4a3f324 other_cp_b 0 10:49:13 2988011440mS ISDNL3Evt: v=5 stacknum=5 State, new=DiscReq, old=Active id=10 10:49:13 2988011448mS ISDNL3Evt: v=5 stacknum=5 State, new=NullState, old=DiscReq id=10 10:49:13 2988011449mS CMLineRx: v=5 CMReleaseComp Line: type=Q931Line 5 Call: lid=5 id=10 in=1 BChan: slot=0 chan=1 10:49:13 2988011449mS CMCallEvt: c0a8000a0000000a 5.10.1 -1 Q931 Trunk:5 CHAN=1: StateChange: END=X CMCSCompleted->CMCSDelete 10:49:13 2988011449mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:13 2988011450mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:13 2988011450mS CMCallEvt: c0a8000a0000000a 5.10.1 -1 BaseEP: DELETE CMEndpoint f163353c TOTAL NOW=1 CALL_LIST=0 10:49:14 2988012003mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Menu Key Pressed 12:I 10:49:14 2988012004mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Feature Key Pressed 6:DCPLFeatureDrop 10:49:14 2988012005mS CMExtnEvt: jessenmacher: CMExtnHandler::SetCurrent( id: 688290->0 ) 10:49:14 2988012005mS CMCallEvt: c0a8000a000a80a2 0.688290.0 -1 jessenmacher.-1: StateChange: END=X CMCSCompletedTone->CMCSDelete 10:49:14 2988012005mS CMExtnEvt: v=12 State, new=PortRecoverDelay old=CMESCompleted,0,0,jessenmacher 10:49:14 2988012006mS CMTARGET: c0a8000a000a80a2 0.688290.0 -1 BaseEP: ~CMTargetHandler f1749e0c ep f48686dc 10:49:14 2988012006mS CMCallEvt: c0a8000a000a80a2 0.688290.0 -1 BaseEP: DELETE CMEndpoint f48686dc TOTAL NOW=0 CALL_LIST=0 10:49:14 2988012009mS CMMap: a=21.11 b=10.14 M02 10:49:14 2988012010mS CMMap: a=21.11 b=0.0 T0 10:49:14 2988012011mS CMMap: a=21.11 b=0.0 DTMF::~DTMF freed CMRTUnknown(f5397878) resource busy 1, total 45 10:49:15 2988013435mS CMExtnEvt: mstevenson: Recover Timer reason=CMTRWrapUp 10:49:15 2988013435mS CMExtnEvt: v=13 State, new=Idle old=PortRecoverDelay,0,0,mstevenson 10:49:16 2988014005mS CMExtnEvt: jessenmacher: Recover Timer reason=CMTRWrapUp 10:49:16 2988014005mS CMExtnEvt: v=12 State, new=Idle old=PortRecoverDelay,0,0,jessenmacher 10:49:16 2988014671mS H323Evt: Recv: RegistrationRequest 192.168.252.132; Extn(601), time since last RRQ-KA 55040, Endpoints registered: 13; Endpoints in registration: 0 10:49:16 2988015713mS RES: Fri 22/9/2017 10:49:17 FreeMem=47707476 Heap=45506708(3) Cache=2200768 MemObjs=33931(36418) CMMsg=8(9) ASN=0 Buff=5200 1355 1000 7364 5 Links=85060(85971) BTree=3403(6946) CPU=17.33% CPUStats=16.06%/2/5/144/12356/15010/00.07%/0 /02.77% MCR=0 MCW=0 10:49:16 2988015713mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=94 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:49:16 2988015713mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:49:16 2988015713mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:49:16 2988015894mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 5 10:49:16 2988015896mS CMCallEvt: 0000000000000000 0.688295.0 -1 BaseEP: NEW CMEndpoint f48686dc TOTAL NOW=1 CALL_LIST=0 10:49:16 2988015896mS CMCallEvt: 0000000000000000 0.688295.0 -1 jessenmacher.-1: NEW CMExtnEndpoint f48686dc, Name=jessenmacher, Extn=361, Phys Extn=361 10:49:16 2988015896mS CMCallEvt: CREATE CALL:188903 (f162ca00) 10:49:16 2988015896mS CMCallEvt: 0000000000000000 0.688296.0 -1 BaseEP: NEW CMEndpoint f171e7e8 TOTAL NOW=2 CALL_LIST=0 10:49:16 2988015899mS CMExtnEvt: jessenmacher: CMExtnHandler::SetCurrent( id: 0->688295 ) 10:49:16 2988015899mS CMCallEvt: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: StateChange: END=A CMCSIdle->CMCSDialInitiated 10:49:16 2988015899mS CMExtnEvt: v=12 State, new=Dialling old=Idle,0,0,jessenmacher 10:49:16 2988015900mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party= sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:16 2988015900mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:16 2988015901mS CMCallEvt: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: StateChange: END=A CMCSDialInitiated->CMCSDialling 10:49:16 2988015902mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:16 2988015902mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=5 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:16 2988015903mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=5 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:16 2988015904mS CD: CALL: 0.688295.0 BState=Idle Cut=0 Music=0.0 Aend="jessenmacher(361)" (10.14) Bend="" [] (0.0) CalledNum=5 () CallingNum=361 (jessenmacher) Internal=1 Time=8 AState=Dialling 10:49:17 2988016838mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 1 10:49:17 2988016839mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:17 2988016839mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=51 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:17 2988016839mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=51 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:18 2988017418mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 2 10:49:18 2988017418mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:18 2988017419mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:18 2988017419mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=512 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:18 2988017605mS H323Evt: Recv: RegistrationRequest 192.168.1.105; Extn(253), time since last RRQ-KA 55011, Endpoints registered: 13; Endpoints in registration: 0 10:49:18 2988017665mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 4 10:49:18 2988017666mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:18 2988017666mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=5124 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:18 2988017666mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=5124 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:18 2988017962mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 8 10:49:18 2988017963mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:18 2988017963mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=51248 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:18 2988017964mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=51248 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:19 2988018367mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 6 10:49:19 2988018367mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:19 2988018368mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512486 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:19 2988018368mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=512486 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:19 2988018631mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 2 10:49:19 2988018632mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:19 2988018632mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=5124862 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:19 2988018632mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=5124862 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:19 2988018989mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 8 10:49:19 2988018989mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:19 2988018990mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=51248628 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:19 2988018990mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=51248628 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:20 2988019242mS H323Evt: Recv: RegistrationRequest 192.168.1.102; Extn(250), time since last RRQ-KA 55012, Endpoints registered: 13; Endpoints in registration: 0 10:49:21 2988020651mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 2 10:49:21 2988020651mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:21 2988020652mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512486282 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:21 2988020652mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=512486282 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:21 2988020714mS RES: Fri 22/9/2017 10:49:22 FreeMem=47680580 Heap=45506708(3) Cache=2173872 MemObjs=33956(36418) CMMsg=8(9) ASN=0 Buff=5200 1355 1000 7363 5 Links=85063(85971) BTree=3398(6946) CPU=17.10% CPUStats=15.96%/1/5/144/12406/15010/00.10%/0 /02.74% MCR=0 MCW=0 10:49:21 2988020714mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=95 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:49:21 2988020715mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:49:21 2988020715mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:49:21 2988020899mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 5 10:49:21 2988020900mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:21 2988020900mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=5124862825 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:21 2988020900mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=5124862825 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:22 2988021154mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 6 10:49:22 2988021154mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:22 2988021155mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=51248628256 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:22 2988021155mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=51248628256 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:22 2988021434mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Digit Key Pressed 1 10:49:22 2988021434mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: Setting Hard Timer 4000 10:49:22 2988021435mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512486282561 sub= calling=361 calling_sub= dir=out complete=0 ses=0 10:49:22 2988021435mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=512486282561 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:23 2988022221mS H323Evt: Recv: RegistrationRequest 192.168.1.104; Extn(252), time since last RRQ-KA 55015, Endpoints registered: 13; Endpoints in registration: 0 10:49:24 2988023425mS H323Evt: Recv: RegistrationRequest 192.168.1.106; Extn(254), time since last RRQ-KA 55012, Endpoints registered: 13; Endpoints in registration: 0 10:49:27 2988025340mS H323Evt: Recv: RegistrationRequest 192.168.1.103; Extn(251), time since last RRQ-KA 55012, Endpoints registered: 13; Endpoints in registration: 0 10:49:27 2988025434mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: TimerExpired cause=CMTCDelayedProcessing 10:49:27 2988025434mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=512486282561 sub= calling=361 calling_sub= dir=out complete=1 ses=0 10:49:27 2988025434mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: ADD TARGET (N): number=512486282561 type=100 depth=1 nobar=1 setorig=1 ses=0 10:49:27 2988025435mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: USER SC: 512486282561 3 12486282561 sc=type=Dial code=5N;, num=Ns9892698242 10:49:27 2988025435mS CMARS: FindActiveARSByGroupID GroupID=0 - Not Found 10:49:27 2988025435mS CMLRQ: FindActiveLRQByGroupID GroupID=0 - Not Found 10:49:27 2988025436mS CMCallEvt: 0000000000000000 0.688297.0 -1 BaseEP: NEW CMEndpoint f163353c TOTAL NOW=3 CALL_LIST=1 10:49:27 2988025436mS CMTARGET: ISDN BChannel 23: in-service check = 1 10:49:27 2988025436mS CMTARGET: ISDN BChannel 23: in-service check = 1 10:49:27 2988025438mS CMTARGET: DIAL LINE: 188903 GROUP = 0 SUCCESS = f163353c 10:49:27 2988025438mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: INITIAL TARGETING SUCCEEDED 10:49:27 2988025438mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: GetNoAnswerTimer:15 10:49:27 2988025439mS CMCallEvt: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: StateChange: END=A CMCSDialling->CMCSDialled 10:49:27 2988025439mS CMExtnEvt: v=12 State, new=Proceeding old=Dialling,0,0,jessenmacher 10:49:27 2988025439mS CMCallEvt: 0000000000000000 0.688296.0 188903 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering 10:49:27 2988025440mS CMCallEvt: c0a8000a000a80a9 0.688297.0 188903 Q931 Trunk:5 CHAN=23: StateChange: END=T CMCSIdle->CMCSOffering 10:49:27 2988025440mS PRN: Setting configured voice gain for ch 23. 10:49:27 2988025441mS CMLineTx: v=5 CMSetup Line: type=Q931Line 5 Call: lid=0 id=688297 in=0 Called[12486282561] Type=National (2) Reason=CMDRdirect Calling[9892698242] Type=National Plan=ISDN BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw BChan: slot=0 chan=23 Timed: 22/09/17 10:49 Locale: enu 10:49:27 2988025441mS CD: CALL: 0.688295.0 BState=Idle Cut=1 Music=0.0 Aend="jessenmacher(361)" (10.14) Bend="Line 5" [Line 5] (0.0) CalledNum=512486282561 () CallingNum=361 (jessenmacher) Internal=0 Time=9545 AState=Dialled 10:49:27 2988025443mS ISDNL3Evt: v=5 stacknum=5 State, new=Initiated, old=NullState id=688297 10:49:27 2988025465mS ISDNL3Evt: v=5 stacknum=5 State, new=Proceeding, old=Initiated id=688297 10:49:27 2988025466mS CMLineRx: v=5 CMProceeding Line: type=Q931Line 5 Call: lid=0 id=688297 in=0 BChan: slot=0 chan=23 10:49:27 2988025466mS CMCallEvt: 0000000000000000 0.688296.0 188903 TargetingEP: RequestEnd c0a8000a000a80a9 0.688297.0 188903 Q931 Trunk:5 CHAN=23 10:49:27 2988025466mS CMTARGET: c0a8000a000a80a7 0.688295.0 188903 jessenmacher.0: CancelTimer CMTCNoAnswerTimeout 10:49:27 2988025467mS CMCallEvt: 0000000000000000 0.688296.0 -1 BaseEP: DELETE CMEndpoint f171e7e8 TOTAL NOW=2 CALL_LIST=1 10:49:27 2988025467mS CMCallEvt: c0a8000a000a80a9 0.688297.0 188903 Q931 Trunk:5 CHAN=23: StateChange: END=B CMCSOffering->CMCSAccept 10:49:27 2988025468mS CD: CALL: 0.688295.0 BState=Ringing Cut=3 Music=0.0 Aend="jessenmacher(361)" (10.14) Bend="Line 5" [Line 5] (3.24) CalledNum=12486282561 () CallingNum=361 (jessenmacher) Internal=0 Time=9572 AState=Dialled 10:49:27 2988025470mS CMMap: PCG::MapBChan pcp[191]b1r0 cp_b f4a5f998 other_cp_b 0 type CGTypeSimple 10:49:27 2988025470mS CMMap: PCG::MapBChan pcp[94]b1r0 cp_b f534dbc8 other_cp_b f4a5f998 type CGTypeSimple 10:49:27 2988025470mS CMMap: a=10.14 b=3.24 M12 10:49:27 2988025720mS RES: Fri 22/9/2017 10:49:27 FreeMem=47677496 Heap=45506708(3) Cache=2170788 MemObjs=33969(36418) CMMsg=8(9) ASN=0 Buff=5200 1350 993 7363 5 Links=85078(85971) BTree=3399(6946) CPU=16.75% CPUStats=16.45%/1/5/144/12372/15010/00.09%/0/ 02.76% MCR=0 MCW=0 10:49:27 2988025720mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=103 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:49:27 2988025720mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:49:27 2988025720mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:49:35 2988033104mS PRN: Optimizing BTree Lists Completed...Started:2988033103 Duration:1 Size:381 Attempted:381 10:49:36 2988034893mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:36 2988034893mS ISDNL3Evt: v=6 stacknum=6 State, new=Present, old=NullState id=6 10:49:36 2988034894mS CMLineRx: v=6 CMSetup Line: type=Q931Line 6 Call: lid=6 id=6 in=1 Called[912486282561] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[519892698242] Type=Unknown Plan=ISDN Pres=Allowed (0) BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw BChan: slot=0 chan=1 10:49:36 2988034894mS PRN: Q931Trunk: Found QBChannel to match 0.1 --> 3.34 10:49:36 2988034894mS CMCallEvt: 0000000000000000 0.688298.0 -1 BaseEP: NEW CMEndpoint f173e278 TOTAL NOW=3 CALL_LIST=1 10:49:36 2988034894mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:36 2988034894mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:36 2988034895mS CMCallEvt: CREATE CALL:188904 (f16720f4) 10:49:36 2988034895mS CMCallEvt: 0000000000000000 0.688299.0 -1 BaseEP: NEW CMEndpoint f171e7e8 TOTAL NOW=4 CALL_LIST=1 10:49:36 2988034898mS CD: CALL: 6.6.1 BState=Idle Cut=1 Music=0.0 Aend="Line 6" (3.34) Bend="" [] (0.0) CalledNum=912486282561 () CallingNum=519892698242 () Internal=0 Time=2 AState=Idle 10:49:36 2988034898mS CMCallEvt: c0a8000a00000006 6.6.1 188904 Q931 Trunk:6 CHAN=1: StateChange: END=A CMCSIdle->CMCSDialInitiated 10:49:36 2988034898mS CMTARGET: c0a8000a00000006 6.6.1 188904 Q931 Trunk:6 CHAN=1: LOOKUP CALL ROUTE: GID=0 type=0 called_party=912486282561 sub= calling=519892698242 calling_sub= dir=in complete=1 ses=0 10:49:36 2988034900mS CMLOGGING: CALL:2017/09/2210:49,00:00:00,000,519892698242,I,912486282561,912486282561,,,,0,,"",0,n/a 10:49:36 2988034900mS CD: CALL: 6.6.1 BState=Idle Cut=0 Music=0.0 Aend="Line 6" (3.34) Bend="" [] (0.0) CalledNum=912486282561 () CallingNum=519892698242 () Internal=0 Time=5 AState=Dialling 10:49:36 2988034901mS CD: CALL: 6.6.1 Deleted 10:49:36 2988034901mS CMLineTx: v=6 CMReleaseComp Line: type=Q931Line 6 Call: lid=6 id=6 in=1 Cause=88, Incompatible destination 10:49:36 2988034901mS CMCallEvt: c0a8000a00000006 6.6.1 -1 Q931 Trunk:6 CHAN=1: StateChange: END=X CMCSDialInitiated->CMCSDelete 10:49:36 2988034901mS CMCallEvt: 0000000000000000 0.688299.0 -1 BaseEP: DELETE CMEndpoint f171e7e8 TOTAL NOW=3 CALL_LIST=1 10:49:36 2988034902mS CMCallEvt: END CALL:188904 (f16720f4) 10:49:36 2988034902mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:36 2988034903mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:49:36 2988034903mS CMTARGET: c0a8000a00000006 6.6.1 -1 BaseEP: ~CMTargetHandler f16a7e80 ep f173e278 10:49:36 2988034903mS CMCallEvt: c0a8000a00000006 6.6.1 -1 BaseEP: DELETE CMEndpoint f173e278 TOTAL NOW=2 CALL_LIST=1 10:49:36 2988034905mS ISDNL3Evt: v=6 stacknum=6 State, new=NullState, old=Present id=6 10:49:36 2988034918mS ISDNL3Evt: v=5 stacknum=5 State, new=ReleaseReq, old=Proceeding id=688297 10:49:36 2988034925mS ISDNL3Evt: v=5 stacknum=5 State, new=NullState, old=ReleaseReq id=688297 10:49:36 2988034926mS CMLineRx: v=5 CMReleaseComp Line: type=Q931Line 5 Call: lid=0 id=688297 in=0 BChan: slot=0 chan=23 Cause=88, Incompatible destination 10:49:36 2988034926mS CMCallEvt: c0a8000a000a80a9 0.688297.0 188903 Q931 Trunk:5 CHAN=23: StateChange: END=B CMCSAccept->CMCSCompleted 10:49:36 2988034928mS CMLOGGING: CALL:2017/09/2210:49,00:00:00,000,361,O,12486282561,512486282561,jessenmacher,,,0,,"",0,n/a 10:49:36 2988034928mS CD: CALL: 0.688295.0 BState=Disconnecting Cut=1 Music=0.0 Aend="jessenmacher(361)" (10.14) Bend="Line 5" [Line 5] (3.24) CalledNum=12486282561 () CallingNum=361 (jessenmacher) Internal=0 Time=19032 AState=Dialled 10:49:36 2988034928mS CD: CALL: 0.688295.0 Deleted 10:49:36 2988034929mS CMExtnEvt: jessenmacher: CALL LOST (CMCauseIncompatible) 10:49:36 2988034929mS CMExtnEvt: jessenmacher: Extn(361) Calling Party Number(361) Type(CMNTypeInternal) 10:49:36 2988034929mS CMCallEvt: c0a8000a000a80a7 0.688295.0 -1 jessenmacher.0: StateChange: END=X CMCSDialled->CMCSCompletedTone 10:49:36 2988034930mS CMExtnEvt: v=12 State, new=CMESCompleted old=Proceeding,0,0,jessenmacher 10:49:36 2988034930mS CMCallEvt: c0a8000a000a80a9 0.688297.0 -1 Q931 Trunk:5 CHAN=23: StateChange: END=X CMCSCompleted->CMCSDelete 10:49:36 2988034931mS CMCallEvt: END CALL:188903 (f162ca00) 10:49:36 2988034931mS CMTARGET: ISDN BChannel 23: in-service check = 1 10:49:36 2988034932mS CMTARGET: ISDN BChannel 23: in-service check = 1 10:49:36 2988034932mS CMCallEvt: c0a8000a000a80a9 0.688297.0 -1 BaseEP: DELETE CMEndpoint f163353c TOTAL NOW=1 CALL_LIST=0 10:49:36 2988034933mS CMMap: PCG::UnmapBChan pcp[191]b1r0 cp_b f4a5f998 other_cp_b f534dbc8 10:49:36 2988034933mS CMMap: a=3.24 b=10.14 M02 10:49:36 2988034934mS CMMap: PCG::UnmapBChan pcp[94]b1r0 cp_b f534dbc8 other_cp_b 0 10:49:36 2988034935mS CMMap: a=21.11 b=0.0 DTMF::AllocateRAS allocated CMRTVoicemail(f5397878) resource busy 2, total 45 10:49:36 2988034935mS CMMap: a=21.11 b=1.65535 T 10:49:36 2988034935mS CMMap: a=21.11 b=10.14 M22 10:49:37 2988035249mS RES: Fri 22/9/2017 10:49:36 FreeMem=47692972 Heap=45506708(3) Cache=2186264 MemObjs=33935(36418) CMMsg=8(9) ASN=0 Buff=5200 1339 1000 7364 5 Links=85081(85971) BTree=3398(6946) CPU=17.28% CPUStats=18.79%/10/17/144/11982/15010/00.35% /0/02.81% MCR=0 MCW=0 10:49:37 2988035250mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=96 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:49:37 2988035250mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:49:37 2988035250mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:49:38 2988036446mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Menu Key Pressed 12:I 10:49:38 2988036448mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,361: Feature Key Pressed 6:DCPLFeatureDrop 10:49:38 2988036448mS CMExtnEvt: jessenmacher: CMExtnHandler::SetCurrent( id: 688295->0 ) 10:49:38 2988036449mS CMCallEvt: c0a8000a000a80a7 0.688295.0 -1 jessenmacher.-1: StateChange: END=X CMCSCompletedTone->CMCSDelete 10:49:38 2988036449mS CMExtnEvt: v=12 State, new=PortRecoverDelay old=CMESCompleted,0,0,jessenmacher 10:49:38 2988036449mS CMTARGET: c0a8000a000a80a7 0.688295.0 -1 BaseEP: ~CMTargetHandler f1749e0c ep f48686dc 10:49:38 2988036450mS CMCallEvt: c0a8000a000a80a7 0.688295.0 -1 BaseEP: DELETE CMEndpoint f48686dc TOTAL NOW=0 CALL_LIST=0 10:49:38 2988036453mS CMMap: a=21.11 b=10.14 M02 10:49:38 2988036453mS CMMap: a=21.11 b=0.0 T0 10:49:38 2988036454mS CMMap: a=21.11 b=0.0 DTMF::~DTMF freed CMRTUnknown(f5397878) resource busy 1, total 45 10:49:40 2988038449mS CMExtnEvt: jessenmacher: Recover Timer reason=CMTRWrapUp 10:49:40 2988038449mS CMExtnEvt: v=12 State, new=Idle old=PortRecoverDelay,0,0,jessenmacher 10:49:40 2988038801mS CMExtnEvt: jpulaskey: No user activity 10:49:58 2988056524mS H323Evt: Recv: RegistrationRequest 192.168.252.134; Extn(604), time since last RRQ-KA 55041, Endpoints registered: 13; Endpoints in registration: 0 10:49:59 2988057130mS H323Evt: Recv: RegistrationRequest 192.168.252.139; Extn(612), time since last RRQ-KA 55042, Endpoints registered: 13; Endpoints in registration: 0 10:50:04 2988062519mS H323Evt: Recv: RegistrationRequest 192.168.252.136; Extn(606), time since last RRQ-KA 55041, Endpoints registered: 13; Endpoints in registration: 0 10:50:04 2988062734mS H323Evt: Recv: RegistrationRequest 192.168.252.138; Extn(611), time since last RRQ-KA 55042, Endpoints registered: 13; Endpoints in registration: 0 10:50:04 2988062796mS H323Evt: Recv: RegistrationRequest 192.168.252.135; Extn(605), time since last RRQ-KA 55042, Endpoints registered: 13; Endpoints in registration: 0 ********** SysMonitor v9.1.6.0 build 153 [connected to 192.168.0.10 (Huron County)] ********** 10:50:06 2988064321mS PRN: Monitor Status IP 500 V2 9.1.6.0 build 153 10:50:06 2988064321mS PRN: LAW=U PRI=2, BRI=0, ALOG=4, VCOMP=10, MDM=0, WAN=0, MODU=5 LANM=0 CkSRC=5 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=0(TOT=188904) 10:50:06 2988064448mS H323Evt: Recv: RegistrationRequest 192.168.252.137; Extn(609), time since last RRQ-KA 55047, Endpoints registered: 13; Endpoints in registration: 0 10:50:06 2988065500mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:50:06 2988065501mS ISDNL3Evt: v=6 stacknum=6 State, new=Present, old=NullState id=16 10:50:06 2988065502mS CMLineRx: v=6 CMSetup Line: type=Q931Line 6 Call: lid=6 id=16 in=1 Called[9892697971] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[519894140637] Type=Unknown Plan=ISDN Pres=Allowed (0) BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw BChan: slot=0 chan=1 IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Unavailable Display [Unavailable] 10:50:06 2988065502mS PRN: Q931Trunk: Found QBChannel to match 0.1 --> 3.34 10:50:06 2988065502mS CMCallEvt: 0000000000000000 0.688300.0 -1 BaseEP: NEW CMEndpoint f163353c TOTAL NOW=1 CALL_LIST=0 10:50:06 2988065503mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:50:06 2988065503mS CMTARGET: ISDN BChannel 1: in-service check = 1 10:50:06 2988065503mS CMCallEvt: CREATE CALL:188905 (f162ca00) 10:50:06 2988065503mS CMCallEvt: 0000000000000000 0.688301.0 -1 BaseEP: NEW CMEndpoint f171e7e8 TOTAL NOW=2 CALL_LIST=0 10:50:06 2988065506mS CD: CALL: 6.16.1 BState=Idle Cut=1 Music=0.0 Aend="Line 6" (3.34) Bend="" [] (0.0) CalledNum=9892697971 () CallingNum=519894140637 (Unavailable) Internal=0 Time=3 AState=Idle 10:50:06 2988065506mS CMCallEvt: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: StateChange: END=A CMCSIdle->CMCSDialInitiated 10:50:06 2988065507mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: LOOKUP CALL ROUTE: GID=0 type=0 called_party=9892697971 sub= calling=519894140637 calling_sub= dir=in complete=1 ses=0 10:50:06 2988065507mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: SET BESTMATCH: length 10 vs -1 match=9892697971 dest=Public Guardian 10:50:06 2988065507mS CMCallEvt: Priority hike: call 188905 priority 0->1 10:50:06 2988065507mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: LOOKUP ICR: DDI= CGPN=519894140637 (Destination Public Guardian ) => CDPN=Public Guardian 10:50:06 2988065508mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: ADD TARGET (N): number=Public Guardian type=0 depth=1 nobar=1 setorig=1 ses=0 10:50:06 2988065508mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: HG(Public Guardian,762,192.168.0.10) Requires Routing To Master(1). IsLocalExecutive(1) 10:50:06 2988065508mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: HG call targeting occuring here 10:50:06 2988065508mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: PrimeForHGTarget: Public Guardian setorig=1 recall=0 resetExtnVars 1 10:50:06 2988065508mS CMCallEvt: Priority hike: call 188905 priority 1->5 10:50:06 2988065508mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: AddHGTarget Public Guardian (depth=1) allowq=1 type=CMNTypeUnknown 10:50:06 2988065508mS CMCallEvt: 0000000000000000 0.688302.0 -1 BaseEP: NEW CMEndpoint f4ace1fc TOTAL NOW=3 CALL_LIST=1 10:50:06 2988065509mS CMTARGET: FoundKnownSystemTargets ICR cache hit 10:50:06 2988065509mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: INITIAL TARGETING SUCCEEDED 10:50:06 2988065509mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: GetNoAnswerTimer:20 10:50:06 2988065509mS CMCallEvt: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: StateChange: END=A CMCSDialInitiated->CMCSDialled 10:50:06 2988065510mS CMLineTx: v=6 CMProceeding Line: type=Q931Line 6 Call: lid=6 id=16 in=1 BChan: slot=0 chan=1 10:50:06 2988065510mS CMCallEvt: 0000000000000000 0.688301.0 188905 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering 10:50:06 2988065511mS CMCallEvt: c0a8000a000a80ae 0.688302.0 188905 ACDTep(Public Guardian): StateChange: END=T CMCSIdle->CMCSOffering 10:50:06 2988065511mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: CancelTimer CMTCNoAnswerTimeout 10:50:06 2988065511mS CMCallEvt: c0a8000a000a80ae 0.688302.0 188905 ACDTep(Public Guardian): StateChange: END=T CMCSOffering->CMCSRinging 10:50:06 2988065512mS CMCallEvt: 0000000000000000 0.688301.0 188905 TargetingEP: StateChange: END=B CMCSOffering->CMCSRinging 10:50:06 2988065512mS CMCallEvt: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: StateChange: END=A CMCSDialled->CMCSRingBack 10:50:06 2988065512mS CMLineTx: v=6 CMAlerting Line: type=Q931Line 6 Call: lid=6 id=16 in=1 BChan: slot=0 chan=1 10:50:06 2988065514mS CD: CALL: 6.16.1 BState=Ringing Cut=1 Music=2.0 Aend="Line 6" (3.34) Bend="Public Guardian(762)" [] (0.0) CalledNum=762 (Public Guardian) CallingNum=519894140637 (Unavailable) Internal=0 Time=11 AState=Ringing 10:50:06 2988065516mS CMMap: a=3.34 b=0.0 R1 10:50:06 2988065517mS CD: CALL: 6.16.1 BState=Ringing Cut=1 Music=2.0 Aend="Line 6" (3.34) Bend="Public Guardian(762)" [] (0.0) CalledNum=762 (Public Guardian) CallingNum=519894140637 (Unavailable) Internal=0 Time=13 AState=Ringing 10:50:06 2988065517mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: PrimeForHGTarget: Public Guardian setorig=0 recall=0 resetExtnVars 1 10:50:06 2988065517mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: AddHGTarget Public Guardian (depth=0) allowq=0 type=CMNTypeUnknown 10:50:06 2988065517mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: AddHGTargetRingGroup Public Guardian starting at 1 10:50:06 2988065518mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: ADD USER: jpeyerk depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=1 type(CMNTypeUnknown) incl(0x0) excpt(0x3c), allow_redir(1) remote=00000000 simult 0 (0) 10:50:06 2988065518mS CMCallEvt: 0000000000000000 0.688303.0 -1 BaseEP: NEW CMEndpoint f48686dc TOTAL NOW=4 CALL_LIST=1 10:50:06 2988065518mS CMCallEvt: 0000000000000000 0.688303.0 -1 jpeyerk.-1: NEW CMExtnEndpoint f48686dc, Name=jpeyerk, Extn=393, Phys Extn=393 10:50:06 2988065519mS CMTARGET: c0a8000a000a80af 0.688303.0 188905 jpeyerk.0: ADD PRIMARY 10:50:06 2988065519mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: ADD USER: akidd depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=1 type(CMNTypeUnknown) incl(0x0) excpt(0x3c), allow_redir(1) remote=00000000 simult 0 (0) 10:50:06 2988065520mS CMCallEvt: 0000000000000000 0.688304.0 -1 BaseEP: NEW CMEndpoint f47e08cc TOTAL NOW=5 CALL_LIST=1 10:50:06 2988065520mS CMCallEvt: 0000000000000000 0.688304.0 -1 akidd.-1: NEW CMExtnEndpoint f47e08cc, Name=akidd, Extn=394, Phys Extn=394 10:50:06 2988065521mS CMTARGET: c0a8000a000a80b0 0.688304.0 188905 akidd.0: ADD PRIMARY 10:50:06 2988065521mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: ADD USER: kcase depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=1 type(CMNTypeUnknown) incl(0x0) excpt(0x3c), allow_redir(1) remote=00000000 simult 0 (0) 10:50:06 2988065521mS CMCallEvt: 0000000000000000 0.688305.0 -1 BaseEP: NEW CMEndpoint f4872060 TOTAL NOW=6 CALL_LIST=1 10:50:06 2988065521mS CMCallEvt: 0000000000000000 0.688305.0 -1 kcase.-1: NEW CMExtnEndpoint f4872060, Name=kcase, Extn=392, Phys Extn=392 10:50:06 2988065522mS CMTARGET: c0a8000a000a80b1 0.688305.0 188905 kcase.0: ADD PRIMARY 10:50:06 2988065523mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: SelectTargetAvailable 3 targets 10:50:06 2988065523mS CMCallEvt: c0a8000a000a80af 0.688303.0 188905 jpeyerk.0: StateChange: END=T CMCSIdle->CMCSOffering 10:50:06 2988065524mS CMExtnEvt: jpeyerk: CMExtnHandler::SetCurrent( id: 0->688303 ) 10:50:06 2988065524mS CMCallEvt: c0a8000a000a80af 0.688303.0 188905 jpeyerk.0: StateChange: END=T CMCSOffering->CMCSRinging 10:50:06 2988065524mS CMExtnEvt: v=2 State, new=Ringing old=Idle,0,0,jpeyerk 10:50:06 2988065526mS CMCallEvt: c0a8000a000a80b0 0.688304.0 188905 akidd.0: StateChange: END=T CMCSIdle->CMCSOffering 10:50:06 2988065526mS CMExtnEvt: akidd: CMExtnHandler::SetCurrent( id: 0->688304 ) 10:50:06 2988065526mS CMCallEvt: c0a8000a000a80b0 0.688304.0 188905 akidd.0: StateChange: END=T CMCSOffering->CMCSRinging 10:50:06 2988065526mS CMExtnEvt: v=3 State, new=Ringing old=Idle,0,0,akidd 10:50:06 2988065528mS CMCallEvt: c0a8000a000a80b1 0.688305.0 188905 kcase.0: StateChange: END=T CMCSIdle->CMCSOffering 10:50:06 2988065528mS CMExtnEvt: kcase: CMExtnHandler::SetCurrent( id: 0->688305 ) 10:50:06 2988065529mS CMCallEvt: c0a8000a000a80b1 0.688305.0 188905 kcase.0: StateChange: END=T CMCSOffering->CMCSRinging 10:50:06 2988065529mS CMExtnEvt: v=1 State, new=Ringing old=Idle,0,0,kcase 10:50:06 2988065530mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: GetNoAnswerTimer:20 10:50:06 2988065531mS CD: CALL: 6.16.1 BState=Ringing Cut=1 Music=2.0 Aend="Line 6" (3.34) Bend="Public Guardian(762)" [jpeyerk(393),akidd(394),kcase(392)] (0.0) CalledNum=762 (Public Guardian) CallingNum=519894140637 (Unavailable) Internal=0 Time=28 ASt ate=Ringing 10:50:06 2988065533mS ISDNL3Evt: v=6 stacknum=6 State, new=ICProceeding, old=Present id=16 10:50:06 2988065533mS ISDNL3Evt: v=6 stacknum=6 State, new=Received, old=ICProceeding id=16 10:50:06 2988065666mS RES: Fri 22/9/2017 10:50:07 FreeMem=47643208 Heap=45506708(3) Cache=2136500 MemObjs=33991(36418) CMMsg=8(9) ASN=0 Buff=5200 1354 997 7363 5 Links=85081(85971) BTree=3400(6946) CPU=16.31% CPUStats=16.35%/2/5/144/12327/15010/00.10%/0/ 02.74% MCR=0 MCW=0 10:50:06 2988065666mS RES2: IP 500 V2 9.1.6.0 build 153 Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=98 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=51(TLS=6) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034 10:50:06 2988065666mS RES4: XML MemObjs=63 PoolMem=5796992(3) FreePoolMem=5781688(0) 10:50:06 2988065666mS RES5: CLog MemObjs=4853 FreePoolMem(Objs)=7644(147) TotalMem=704500 10:50:06 2988065858mS H323Evt: Recv: RegistrationRequest 192.168.252.133; Extn(495), time since last RRQ-KA 55040, Endpoints registered: 13; Endpoints in registration: 0 10:50:07 2988066913mS SIP Tx: UDP 10.1.0.21:5060 -> 192.168.1.108:5060 OPTIONS sip:192.168.1.108 SIP/2.0 Via: SIP/2.0/UDP 10.1.0.21:5060;rport;branch=z9hG4bK0ae7c29b1437ff0238ec78401426b20a From: ;tag=6ce088f4c89d31a1 To: Call-ID: 0960e4858131aa1d21fff51e733e3c8a CSeq: 621717382 OPTIONS Contact: Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,NOTIFY,UPDATE Supported: timer User-Agent: IP Office 9.1.6.0 build 153 Content-Length: 0 10:50:07 2988066934mS SIP Rx: UDP 192.168.1.108:5060 -> 10.1.0.21:5060 SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.0.21:5060;branch=z9hG4bK0ae7c29b1437ff0238ec78401426b20a;received=10.1.0.21;rport=5060 From: ;tag=6ce088f4c89d31a1 To: ;tag=1c1507599569 Call-ID: 0960e4858131aa1d21fff51e733e3c8a CSeq: 621717382 OPTIONS Contact: ;expires=0 Supported: 100rel Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: MP-124E FXS/v.6.60A.332.002 X-Resources: telchs=11/0;mediachs=0/0 Accept: application/sdp, application/simple-message-summary, message/sipfrag Content-Type: application/sdp Content-Length: 262 v=0 o=AudiocodesGW 1507629800 1507629795 IN IP4 192.168.1.108 s=Phone-Call c=IN IP4 192.168.1.108 t=0 0 m=audio 6000 RTP/AVP 8 0 101 a=ptime:20 a=sendrecv a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15,16 10:50:08 2988067732mS CMCallEvt: c0a8000a000a80b0 0.688304.0 188905 akidd.0: StateChange: END=T CMCSRinging->CMCSConnReq 10:50:08 2988067732mS CMCallEvt: 0000000000000000 0.688301.0 188905 TargetingEP: RequestEnd c0a8000a000a80b0 0.688304.0 188905 akidd.0 10:50:08 2988067733mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: Removed HG from Callinfo 10:50:08 2988067733mS CMCallEvt: c0a8000a000a80ae 0.688302.0 188905 ACDTep(Public Guardian): StateChange: END=??? CMCSRinging->CMCSDelete 10:50:08 2988067733mS CMCallEvt: c0a8000a000a80ae 0.688302.0 -1 BaseEP: DELETE CMEndpoint f4ace1fc TOTAL NOW=5 CALL_LIST=1 10:50:08 2988067734mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: CancelTimer CMTCNoAnswerTimeout 10:50:08 2988067734mS CMCallEvt: 0000000000000000 0.688301.0 -1 BaseEP: DELETE CMEndpoint f171e7e8 TOTAL NOW=4 CALL_LIST=1 10:50:08 2988067735mS CMExtnEvt: jpeyerk: CALL LOST (CMCauseAnsweredByOther) 10:50:08 2988067735mS CMExtnEvt: jpeyerk: Extn(393) Calling Party Number(519894140637) Type(CMNTypeUnknown) 10:50:08 2988067735mS CMCallEvt: c0a8000a000a80af 0.688303.0 -1 jpeyerk.0: StateChange: END=X CMCSRinging->CMCSCompleted 10:50:08 2988067735mS CMExtnEvt: v=2 State, new=PortRecoverDelay old=Ringing,0,0,jpeyerk 10:50:08 2988067736mS CMExtnEvt: jpeyerk: CMExtnHandler::SetCurrent( id: 688303->0 ) 10:50:08 2988067736mS CMCallEvt: c0a8000a000a80af 0.688303.0 -1 jpeyerk.-1: StateChange: END=X CMCSCompleted->CMCSDelete 10:50:08 2988067737mS CMCallEvt: c0a8000a000a80af 0.688303.0 -1 BaseEP: DELETE CMEndpoint f48686dc TOTAL NOW=3 CALL_LIST=1 10:50:08 2988067737mS CMExtnEvt: kcase: CALL LOST (CMCauseAnsweredByOther) 10:50:08 2988067737mS CMExtnEvt: kcase: Extn(392) Calling Party Number(519894140637) Type(CMNTypeUnknown) 10:50:08 2988067737mS CMCallEvt: c0a8000a000a80b1 0.688305.0 -1 kcase.0: StateChange: END=X CMCSRinging->CMCSCompleted 10:50:08 2988067737mS CMExtnEvt: v=1 State, new=PortRecoverDelay old=Ringing,0,0,kcase 10:50:08 2988067738mS CMExtnEvt: kcase: CMExtnHandler::SetCurrent( id: 688305->0 ) 10:50:08 2988067739mS CMCallEvt: c0a8000a000a80b1 0.688305.0 -1 kcase.-1: StateChange: END=X CMCSCompleted->CMCSDelete 10:50:08 2988067739mS CMCallEvt: c0a8000a000a80b1 0.688305.0 -1 BaseEP: DELETE CMEndpoint f4872060 TOTAL NOW=2 CALL_LIST=1 10:50:08 2988067739mS CMExtnEvt: v=3 State, new=Connected old=Ringing,0,0,akidd 10:50:08 2988067740mS CMCallEvt: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: StateChange: END=A CMCSRingBack->CMCSOGConnReq 10:50:08 2988067740mS CMLineTx: v=6 CMConnect Line: type=Q931Line 6 Call: lid=6 id=16 in=1 Called[394] Type=Internal (101) Reason=CMDRdirect BChan: slot=0 chan=1 10:50:08 2988067742mS CD: CALL: 6.16.1 BState=Connected Cut=3 Music=0.0 Aend="Line 6" (3.34) Bend="" [akidd(394)] (11.5) CalledNum=762 (Public Guardian) CallingNum=519894140637 (Unavailable) Internal=0 Time=2238 AState=Connected 10:50:08 2988067743mS CMMap: a=3.34 b=0.0 R0 10:50:08 2988067743mS CMMap: PCG::MapBChan pcp[95]b1r0 cp_b f52161c4 other_cp_b 0 type CGTypeSimple 10:50:08 2988067744mS CMMap: PCG::MapBChan pcp[160]b1r0 cp_b f4a8c1e4 other_cp_b f52161c4 type CGTypeSimple 10:50:08 2988067744mS CMMap: a=3.34 b=11.5 M12 10:50:08 2988067745mS ISDNL3Evt: v=6 stacknum=6 State, new=ConnReq, old=Received id=16 10:50:08 2988067746mS CMExtnEvt: jpeyerk: Recover Timer reason=CMTRWrapUp 10:50:08 2988067746mS CMExtnEvt: v=2 State, new=Idle old=PortRecoverDelay,0,0,jpeyerk 10:50:08 2988067750mS CMExtnEvt: kcase: Recover Timer reason=CMTRWrapUp 10:50:08 2988067750mS CMExtnEvt: v=1 State, new=Idle old=PortRecoverDelay,0,0,kcase 10:50:08 2988067752mS ISDNL3Evt: v=6 stacknum=6 State, new=Active, old=ConnReq id=16 10:50:08 2988067753mS CMLineRx: v=6 CMConnectAck Line: type=Q931Line 6 Call: lid=6 id=16 in=1 10:50:08 2988067753mS CMCallEvt: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: StateChange: END=A CMCSOGConnReq->CMCSConnected 10:50:08 2988067753mS CMTARGET: c0a8000a00000010 6.16.1 188905 Q931 Trunk:6 CHAN=1: ~CMTargetHandler f1749e0c ep f163353c 10:50:08 2988067754mS CMCallEvt: c0a8000a000a80b0 0.688304.0 188905 akidd.0: StateChange: END=B CMCSConnReq->CMCSConnected ********** Warning: Logging to Screen Stopped **********