telnetbrian
Programmer
Inbound Best Match fails
upgraded to R11.0.4.0 DSS T1
system was super stable passed rigorous tests. a week or so later started having issues
have isolated it down to Best match. have logs. its weird as a reboot of systems and it comes back up...then randomly starts to do it again, then goes from random to every incoming call
example dial from outside to fax---normally goes to ext 3600 and the fax picks up, when issues is happening it goes to auto attendant,
when issue happens it takes 15 seconds to pick up, when not happening its 2-3 seconds
I notice how much more info comes in from the T1 when the issue is not happening....Also look at the best match, it is 0 vs -1 when issue happens and 4 vs -1 when all is well?
i dont beleive it is the Circuit as why would the reboot of the PBX correct the issue?
Log when issue is happening:
486837969mS T1Channel: chan: E&M 9.2: Receive T1EMOffHook
486837969mS T1Channel: chan: E&M 9.2: EventRx T1EMOffHook state=Idle
486837969mS T1Channel: chan: E&M 9.2: StateChange Idle->IncomingHandshake
486837969mS T1DSP: PRIU DSP 3: channel 2 (timeslot 4), speech path on
486837969mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [...t.....T-0.+.........<.\r...........\r.P.\r.....0..\r..] [0x01 0x06 0x00 0x74 0x00 0x00 0x00 0x01 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x11 0x10 0x00 0x00 0x02 0x3c 0xf1 0x0d 0x92 0xb4 0xf5 0x]
486837970mS T1Line: line: 9.2: State= Idle RxMessage: Alert_PreIndication
486837970mS T1Line: line: 9.2: State Change Idle -> IncomingGuard
486837989mS T1Channel: chan: E&M 9.2: StateChange IncomingHandshake->IncomingAlerting
486838089mS T1Channel: chan: E&M 9.2: Transmit T1EMOffHook
486838089mS T1CAS: Channel E&M 9.2: TX: 0000 -> 1111
486838089mS T1Channel: chan: E&M 9.2: StateChange IncomingAlerting->WinkSending
486838289mS T1Channel: chan: E&M 9.2: Transmit T1EMOnHook
486838289mS T1CAS: Channel E&M 9.2: TX: 1111 -> 0000
486838289mS T1Channel: chan: E&M 9.2: StateChange WinkSending->WinkEndGuard
486838339mS T1Channel: chan: E&M 9.2: StateChange WinkEndGuard->WaitForDigits
486838418mS T1DSP: PRIU DSP 3: read tone, port 0, channel 2, tone '3'
486838569mS T1DSP: PRIU DSP 3: read tone, port 0, channel 2, tone '1'
486838703mS T1DSP: PRIU DSP 3: read tone, port 0, channel 2, tone '4'
486838837mS T1DSP: PRIU DSP 3: read tone, port 0, channel 2, tone '3'
486840826mS CMExtnEvt: EmilyBlake:3103 ExtnFault now 1
486844728mS T1DSP: PRIU DSP 3: is alive
486847502mS CMExtnEvt: EmilyBlake:3103 ExtnFault now 0
486847504mS CMExtnEvt: 3103 ReportAttachment type=0
********** SysMonitor v11.0.4.0.0 build 74 [connected to 172.17.42.10 (MiddleSchool)] **********
486850760mS CMExtnEvt: EmilyBlake:3103 ExtnFault now 1
486853339mS T1Channel: chan: E&M 9.2: StateChange WaitForDigits->Talk
486853339mS T1Dialler: dialler: 8.2: Dial First Digit Timeout 15000
486853339mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [......b......T,...8...b..T,..T-.......G..............] [0x01 0x07 0x00 0xa9 0xf0 0x00 0x62 0xf0 0x00 0x00 0x00 0x00 0xf5 0x54 0x2c 0xf4 0x01 0x94 0x38 0x16 0xf0 0x00 0x62 0xf0 0xf5 0x54 0x2c 0xf4 0xf5 0x]
486853340mS T1Line: line: 9.2: State= IncomingGuard RxMessage: Ringing
486853340mS T1Line: line: 9.2: State Change IncomingGuard -> Present
486853340mS T1Line: line: 9.2: Incoming Call from to
486853341mS CMCallEvt: 0000000000000000 0.7873.0 -1 BaseEP: NEW CMEndpoint f171d208 TOTAL NOW=3 CALL_LIST=1
486853341mS CMCallEvt: CREATE CALL:1913 (f1714c78)
486853341mS CMCallEvt: 0000000000000000 0.7874.0 -1 BaseEP: NEW CMEndpoint f172b55c TOTAL NOW=4 CALL_LIST=1
486853344mS CMLineRx: v=9
CMSetup
Line: type=T1Line 9 Call: lid=9 id=7873 in=1
BC: CMTC=Speech CMTM=CallIndSigCon CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=5 chan=3
IE CMIERespondingPartyNumber (230)(P:2 S:100 T:0 N:100 R:4) number=
IE CMIEDeviceDetail (231) ac112a0a00001ec1 LOCALE=enu HW=15 VER=11 class=CMDeviceT1Trunk type=0 number=9 channel=2 features=0x0 rx_gain=32 tx_gain=32
ep_callid=7873 ipaddr=172.17.42.10 apps=0 loc=0 em_a_loc=0 em_d_loc=0 features2=0x0 is_spcall=1 ignores_dtmf=0 avgsid=
486853344mS CMCallEvt: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: StateChange: END=A CMCSIdle->CMCSDialInitiated
486853344mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: Setting Hard Timer 4000
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: LOOKUP CALL ROUTE: GID=0 type=0 called_party= sub= calling= calling_sub= dir=in complete=0 ses=0
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: SET BESTMATCH: length 0 vs -1 match=4680 dest=VM:AutoAttend
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4691 dest=2132
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4685 dest=2904
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2271 dest=Central Office
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4699 dest=VM:AutoAttend
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4681 dest=2169
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4682 dest=2321
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4683 dest=2382
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4690 dest=2903
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4695 dest=2503
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4697 dest=2162
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4694 dest=2902
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4698 dest=2313
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4693 dest=2130
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4686 dest=3888
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=44692 dest=4136
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=3143 dest=3600
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2517 dest=4601
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2848 dest=2606
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2551 dest=1600
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2268 dest=3601
486853347mS CMCallEvt: Priority hike: call 1913 priority 0->1
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: LOOKUP ICR: DDI= CGPN= (Destination VM:AutoAttend ) => CDPN=VM:AutoAttend
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: ADD TARGET (N): number=VM:AutoAttend type=0 depth=1 nobar=1 setorig=1 ses=0
486853348mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: ADD VM TARGET
486853348mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: MakeVoicemailTarget pbx=<null> local=1 type=1
486853348mS CMCallEvt: 0000000000000000 0.7875.0 -1 BaseEP: NEW CMEndpoint f17102d0 TOTAL NOW=5 CALL_LIST=2
486853349mS CMTARGET: ac112a0a00001ec3 0.7875.0 1913 RAS.0: ADD PRIMARY
486853349mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: ADD VM TARGET: SUCCEEDED
486853349mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: CancelTimer CMTCDelayedProcessing
486853349mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: INITIAL TARGETING SUCCEEDED
486853349mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: GetNoAnswerTimer:15
486853349mS CMCallEvt: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: StateChange: END=A CMCSDialInitiated->CMCSDialling
486853350mS CMLineTx: v=9
Log when it is not happening:
1224739mS T1Line: line: 9.1: State= Idle RxMessage: Alert_PreIndication
1224739mS T1Line: line: 9.1: State Change Idle -> IncomingGuard
1224758mS T1Channel: chan: E&M 9.1: StateChange IncomingHandshake->IncomingAlerting
1224858mS T1Channel: chan: E&M 9.1: Transmit T1EMOffHook
1224858mS T1CAS: Channel E&M 9.1: TX: 0000 -> 1111
1224858mS T1Channel: chan: E&M 9.1: StateChange IncomingAlerting->WinkSending
1225058mS T1Channel: chan: E&M 9.1: Transmit T1EMOnHook
1225058mS T1CAS: Channel E&M 9.1: TX: 1111 -> 0000
1225058mS T1Channel: chan: E&M 9.1: StateChange WinkSending->WinkEndGuard
1225108mS T1Channel: chan: E&M 9.1: StateChange WinkEndGuard->WaitForDigits
1225212mS T1DSP: PRIU DSP 3: read tone, port 0, channel 1, tone '3'
1225212mS T1Dialler: dialler: -258258720.1: Receive DTMF 3
1225213mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [.!.3.C%d.T-0.+.....\...=.\r.|.C%....3......"....3..\r..] [0x00 0x21 0x00 0x33 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x13 0x5c 0x00 0x00 0x02 0x3d 0xf1 0x0d 0xf9 0x7c 0xf5 0x]
1225213mS T1Line: line: 9.1: State= IncomingGuard RxMessage: ReceivedDigit
1225213mS T1Line: line: 9.1: Routing Digit Received 3
1225354mS T1DSP: PRIU DSP 3: read tone, port 0, channel 1, tone '1'
1225354mS T1Dialler: dialler: -258258720.1: Receive DTMF 1
1225355mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [.!.1.C%d.T-0.+.....\...=.\r.|.C%....1......"....1..\r..] [0x00 0x21 0x00 0x31 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x13 0x5c 0x00 0x00 0x02 0x3d 0xf1 0x0d 0xf9 0x7c 0xf5 0x]
1225355mS T1Line: line: 9.1: State= IncomingGuard RxMessage: ReceivedDigit
1225355mS T1Line: line: 9.1: Routing Digit Received 1
1225488mS T1DSP: PRIU DSP 3: read tone, port 0, channel 1, tone '4'
1225488mS T1Dialler: dialler: -258258720.1: Receive DTMF 4
1225489mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [.!.4.C%d.T-0.+.....\...=.\r.|.C%....4......"....4..\r..] [0x00 0x21 0x00 0x34 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x13 0x5c 0x00 0x00 0x02 0x3d 0xf1 0x0d 0xf9 0x7c 0xf5 0x]
1225489mS T1Line: line: 9.1: State= IncomingGuard RxMessage: ReceivedDigit
1225489mS T1Line: line: 9.1: Routing Digit Received 4
1225631mS T1DSP: PRIU DSP 3: read tone, port 0, channel 1, tone '3'
1225631mS T1Dialler: dialler: -258258720.1: Receive DTMF 3
1225631mS T1Channel: chan: E&M 9.1: StateChange WaitForDigits->Talk
1225632mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [.!.3.C%d.T-0.+.....\...=.\r.|.C%....3......"....3..\r..] [0x00 0x21 0x00 0x33 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x13 0x5c 0x00 0x00 0x02 0x3d 0xf1 0x0d 0xf9 0x7c 0xf5 0x]
1225632mS T1Line: line: 9.1: State= IncomingGuard RxMessage: ReceivedDigit
1225632mS T1Line: line: 9.1: Routing Digit Received 3
1225632mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [...!.....T-0.\ra$.!.3.C%d.T-0.+.....\...=.\r.|.C%......] [0x00 0x07 0x00 0x21 0xf5 0x1d 0x1b 0xf4 0xf5 0x54 0x2d 0x30 0xf1 0x0d 0x61 0x24 0x00 0x21 0x00 0x33 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x]
1225632mS T1Line: line: 9.1: State= IncomingGuard RxMessage: Ringing
1225632mS T1Line: line: 9.1: State Change IncomingGuard -> Present
1225632mS T1Line: line: 9.1: Incoming Call from to 3143
1225633mS CMCallEvt: 0000000000000000 0.1131.0 -1 BaseEP: NEW CMEndpoint f171bc70 TOTAL NOW=1 CALL_LIST=0
1225633mS CMCallEvt: CREATE CALL:35 (f17219fc)
1225634mS CMCallEvt: 0000000000000000 0.1132.0 -1 BaseEP: NEW CMEndpoint f172513c TOTAL NOW=2 CALL_LIST=0
1225637mS CMLineRx: v=9
CMSetup
Line: type=T1Line 9 Call: lid=9 id=1131 in=1
Called[3143] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[] Type=Unknown Plan=Default Pres=NAInterworking (2)
BC: CMTC=Speech CMTM=CallIndSigCon CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=5 chan=2
IE CMIERespondingPartyNumber (230)(P:2 S:100 T:0 N:100 R:4) number=
IE CMIEDeviceDetail (231) ac112a0a0000046b LOCALE=enu HW=15 VER=11 class=CMDeviceT1Trunk type=0 number=9 channel=1 features=0x0 rx_gain=32 tx_gain=32
ep_callid=1131 ipaddr=172.17.42.10 apps=0 loc=0 em_a_loc=0 em_d_loc=0 features2=0x0 is_spcall=1 ignores_dtmf=0 avgsid=
1225637mS CMCallEvt: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: StateChange: END=A CMCSIdle->CMCSDialInitiated
1225637mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: LOOKUP CALL ROUTE: GID=0 type=0 called_party=3143 sub= calling= calling_sub= dir=in complete=1 ses=0
1225637mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: SET BESTMATCH: length 4 vs -1 match=3143 dest=3600
1225637mS CMCallEvt: Priority hike: call 35 priority 0->1
1225637mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: LOOKUP ICR: DDI= CGPN= (Destination 3600 ) => CDPN=3600
1225637mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: ADD TARGET (N): number=3600 type=0 depth=1 nobar=1 setorig=1 ses=0
1225638mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: SET USER: Extn3600office orig=1
1225638mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: ADD USER: Extn3600office depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeUnknown) incl(0x0) excpt(0x0), allow_redir(1) remote=00000000 simult 0 (0) r_lic=T
1225638mS CMCallEvt: 0000000000000000 0.1133.0 -1 BaseEP: NEW CMEndpoint f1745d38 TOTAL NOW=3 CALL_LIST=1
1225638mS CMCallEvt: 0000000000000000 0.1133.0 -1 Extn3600office.-1: NEW CMExtnEndpoint f1745d38, Name=Extn3600office, Extn=3600, Phys Extn=3600
1225640mS CMTARGET: ac112a0a0000046d 0.1133.0 35 Extn3600office.0: ADD PRIMARY
1225640mS CMTARGET: FoundKnownSystemTargets ICR cache hit
1225640mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: INITIAL TARGETING SUCCEEDED
1225641mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: GetNoAnswerTimer:15
1225641mS CMCallEvt: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: StateChange: END=A CMCSDialInitiated->CMCSDialled
1225641mS CMLineTx: v=9
CMProceeding
Line: type=T1Line 9 Call: lid=9 id=1131 in=1
1225641mS T1Line: line: 9.1: State: Present CMMessage: CMProceeding
1225641mS T1Line: line: 9.1: State Change Present -> ICProceeding
1225642mS CMCallEvt: 0000000000000000 0.1132.0 35 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
1225643mS CMCallEvt: ac112a0a0000046d 0.1133.0 35 Extn3600office.0: StateChange: END=T CMCSIdle->CMCSOffering
1225643mS CMExtnEvt: Extn3600office: CMExtnHandler::SetCurrent( id: 0->1133 )
1225643mS CMExtnTx: v=3600, p1=0
CMSetup
Line: type=AnalogueExtn 5 Call: lid=0 id=1 in=0
Called[3600] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[] Type=Unknown Plan=Default Pres=NAInterworking (2)
BC: CMTC=Speech CMTM=CallIndSigCon CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=6 chan=25
IE CMIERespondingPartyNumber (230)(P:2 S:100 T:0 N:100 R:4) number=
IE CMIEDeviceDetail (231) ac112a0a0000046b LOCALE=enu HW=15 VER=11 class=CMDeviceT1Trunk type=0 number=9 channel=1 features=0x20 rx_gain=32 tx_gain=32
ep_callid=1131 ipaddr=172.17.42.10 apps=0 loc=0 em_a_loc=0 em_d_loc=0 features2=0x0 is_spcall=1 ignores_dtmf=0 avgsid=
IE CMIECalledPartyName (224)(Type=CMNameInternalUser) name=Extn3600office
IE CMIECalledPartyKName (225)(Type=CMNameDefault) name=3600 Office FAX 4064783143
IE CMIEIcrPriorityDetail (239) Priority = 1
IE CMIEMohSourceId (247) MOH Source = 1
UUI type=Local [......2Pd...] [0x01 0x01 0x00 0x00 0x01 0x02 0x32 0x50 0x64 0x00 0x00 0x00 ]
Display [External]
Timed: 26/08/19 10:21
Locale: enu
Any help is greatly appreciated!
upgraded to R11.0.4.0 DSS T1
system was super stable passed rigorous tests. a week or so later started having issues
have isolated it down to Best match. have logs. its weird as a reboot of systems and it comes back up...then randomly starts to do it again, then goes from random to every incoming call
example dial from outside to fax---normally goes to ext 3600 and the fax picks up, when issues is happening it goes to auto attendant,
when issue happens it takes 15 seconds to pick up, when not happening its 2-3 seconds
I notice how much more info comes in from the T1 when the issue is not happening....Also look at the best match, it is 0 vs -1 when issue happens and 4 vs -1 when all is well?
i dont beleive it is the Circuit as why would the reboot of the PBX correct the issue?
Log when issue is happening:
486837969mS T1Channel: chan: E&M 9.2: Receive T1EMOffHook
486837969mS T1Channel: chan: E&M 9.2: EventRx T1EMOffHook state=Idle
486837969mS T1Channel: chan: E&M 9.2: StateChange Idle->IncomingHandshake
486837969mS T1DSP: PRIU DSP 3: channel 2 (timeslot 4), speech path on
486837969mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [...t.....T-0.+.........<.\r...........\r.P.\r.....0..\r..] [0x01 0x06 0x00 0x74 0x00 0x00 0x00 0x01 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x11 0x10 0x00 0x00 0x02 0x3c 0xf1 0x0d 0x92 0xb4 0xf5 0x]
486837970mS T1Line: line: 9.2: State= Idle RxMessage: Alert_PreIndication
486837970mS T1Line: line: 9.2: State Change Idle -> IncomingGuard
486837989mS T1Channel: chan: E&M 9.2: StateChange IncomingHandshake->IncomingAlerting
486838089mS T1Channel: chan: E&M 9.2: Transmit T1EMOffHook
486838089mS T1CAS: Channel E&M 9.2: TX: 0000 -> 1111
486838089mS T1Channel: chan: E&M 9.2: StateChange IncomingAlerting->WinkSending
486838289mS T1Channel: chan: E&M 9.2: Transmit T1EMOnHook
486838289mS T1CAS: Channel E&M 9.2: TX: 1111 -> 0000
486838289mS T1Channel: chan: E&M 9.2: StateChange WinkSending->WinkEndGuard
486838339mS T1Channel: chan: E&M 9.2: StateChange WinkEndGuard->WaitForDigits
486838418mS T1DSP: PRIU DSP 3: read tone, port 0, channel 2, tone '3'
486838569mS T1DSP: PRIU DSP 3: read tone, port 0, channel 2, tone '1'
486838703mS T1DSP: PRIU DSP 3: read tone, port 0, channel 2, tone '4'
486838837mS T1DSP: PRIU DSP 3: read tone, port 0, channel 2, tone '3'
486840826mS CMExtnEvt: EmilyBlake:3103 ExtnFault now 1
486844728mS T1DSP: PRIU DSP 3: is alive
486847502mS CMExtnEvt: EmilyBlake:3103 ExtnFault now 0
486847504mS CMExtnEvt: 3103 ReportAttachment type=0
********** SysMonitor v11.0.4.0.0 build 74 [connected to 172.17.42.10 (MiddleSchool)] **********
486850760mS CMExtnEvt: EmilyBlake:3103 ExtnFault now 1
486853339mS T1Channel: chan: E&M 9.2: StateChange WaitForDigits->Talk
486853339mS T1Dialler: dialler: 8.2: Dial First Digit Timeout 15000
486853339mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [......b......T,...8...b..T,..T-.......G..............] [0x01 0x07 0x00 0xa9 0xf0 0x00 0x62 0xf0 0x00 0x00 0x00 0x00 0xf5 0x54 0x2c 0xf4 0x01 0x94 0x38 0x16 0xf0 0x00 0x62 0xf0 0xf5 0x54 0x2c 0xf4 0xf5 0x]
486853340mS T1Line: line: 9.2: State= IncomingGuard RxMessage: Ringing
486853340mS T1Line: line: 9.2: State Change IncomingGuard -> Present
486853340mS T1Line: line: 9.2: Incoming Call from to
486853341mS CMCallEvt: 0000000000000000 0.7873.0 -1 BaseEP: NEW CMEndpoint f171d208 TOTAL NOW=3 CALL_LIST=1
486853341mS CMCallEvt: CREATE CALL:1913 (f1714c78)
486853341mS CMCallEvt: 0000000000000000 0.7874.0 -1 BaseEP: NEW CMEndpoint f172b55c TOTAL NOW=4 CALL_LIST=1
486853344mS CMLineRx: v=9
CMSetup
Line: type=T1Line 9 Call: lid=9 id=7873 in=1
BC: CMTC=Speech CMTM=CallIndSigCon CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=5 chan=3
IE CMIERespondingPartyNumber (230)(P:2 S:100 T:0 N:100 R:4) number=
IE CMIEDeviceDetail (231) ac112a0a00001ec1 LOCALE=enu HW=15 VER=11 class=CMDeviceT1Trunk type=0 number=9 channel=2 features=0x0 rx_gain=32 tx_gain=32
ep_callid=7873 ipaddr=172.17.42.10 apps=0 loc=0 em_a_loc=0 em_d_loc=0 features2=0x0 is_spcall=1 ignores_dtmf=0 avgsid=
486853344mS CMCallEvt: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: StateChange: END=A CMCSIdle->CMCSDialInitiated
486853344mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: Setting Hard Timer 4000
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: LOOKUP CALL ROUTE: GID=0 type=0 called_party= sub= calling= calling_sub= dir=in complete=0 ses=0
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: SET BESTMATCH: length 0 vs -1 match=4680 dest=VM:AutoAttend
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4691 dest=2132
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4685 dest=2904
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2271 dest=Central Office
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4699 dest=VM:AutoAttend
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4681 dest=2169
486853345mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4682 dest=2321
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4683 dest=2382
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4690 dest=2903
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4695 dest=2503
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4697 dest=2162
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4694 dest=2902
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4698 dest=2313
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4693 dest=2130
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=4686 dest=3888
486853346mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=44692 dest=4136
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=3143 dest=3600
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2517 dest=4601
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2848 dest=2606
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2551 dest=1600
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: AMBIGUITY: match=2268 dest=3601
486853347mS CMCallEvt: Priority hike: call 1913 priority 0->1
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: LOOKUP ICR: DDI= CGPN= (Destination VM:AutoAttend ) => CDPN=VM:AutoAttend
486853347mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: ADD TARGET (N): number=VM:AutoAttend type=0 depth=1 nobar=1 setorig=1 ses=0
486853348mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: ADD VM TARGET
486853348mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: MakeVoicemailTarget pbx=<null> local=1 type=1
486853348mS CMCallEvt: 0000000000000000 0.7875.0 -1 BaseEP: NEW CMEndpoint f17102d0 TOTAL NOW=5 CALL_LIST=2
486853349mS CMTARGET: ac112a0a00001ec3 0.7875.0 1913 RAS.0: ADD PRIMARY
486853349mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: ADD VM TARGET: SUCCEEDED
486853349mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: CancelTimer CMTCDelayedProcessing
486853349mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: INITIAL TARGETING SUCCEEDED
486853349mS CMTARGET: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: GetNoAnswerTimer:15
486853349mS CMCallEvt: ac112a0a00001ec1 9.7873.1 1913 T1 Trunk:9 CHAN=2: StateChange: END=A CMCSDialInitiated->CMCSDialling
486853350mS CMLineTx: v=9
Log when it is not happening:
1224739mS T1Line: line: 9.1: State= Idle RxMessage: Alert_PreIndication
1224739mS T1Line: line: 9.1: State Change Idle -> IncomingGuard
1224758mS T1Channel: chan: E&M 9.1: StateChange IncomingHandshake->IncomingAlerting
1224858mS T1Channel: chan: E&M 9.1: Transmit T1EMOffHook
1224858mS T1CAS: Channel E&M 9.1: TX: 0000 -> 1111
1224858mS T1Channel: chan: E&M 9.1: StateChange IncomingAlerting->WinkSending
1225058mS T1Channel: chan: E&M 9.1: Transmit T1EMOnHook
1225058mS T1CAS: Channel E&M 9.1: TX: 1111 -> 0000
1225058mS T1Channel: chan: E&M 9.1: StateChange WinkSending->WinkEndGuard
1225108mS T1Channel: chan: E&M 9.1: StateChange WinkEndGuard->WaitForDigits
1225212mS T1DSP: PRIU DSP 3: read tone, port 0, channel 1, tone '3'
1225212mS T1Dialler: dialler: -258258720.1: Receive DTMF 3
1225213mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [.!.3.C%d.T-0.+.....\...=.\r.|.C%....3......"....3..\r..] [0x00 0x21 0x00 0x33 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x13 0x5c 0x00 0x00 0x02 0x3d 0xf1 0x0d 0xf9 0x7c 0xf5 0x]
1225213mS T1Line: line: 9.1: State= IncomingGuard RxMessage: ReceivedDigit
1225213mS T1Line: line: 9.1: Routing Digit Received 3
1225354mS T1DSP: PRIU DSP 3: read tone, port 0, channel 1, tone '1'
1225354mS T1Dialler: dialler: -258258720.1: Receive DTMF 1
1225355mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [.!.1.C%d.T-0.+.....\...=.\r.|.C%....1......"....1..\r..] [0x00 0x21 0x00 0x31 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x13 0x5c 0x00 0x00 0x02 0x3d 0xf1 0x0d 0xf9 0x7c 0xf5 0x]
1225355mS T1Line: line: 9.1: State= IncomingGuard RxMessage: ReceivedDigit
1225355mS T1Line: line: 9.1: Routing Digit Received 1
1225488mS T1DSP: PRIU DSP 3: read tone, port 0, channel 1, tone '4'
1225488mS T1Dialler: dialler: -258258720.1: Receive DTMF 4
1225489mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [.!.4.C%d.T-0.+.....\...=.\r.|.C%....4......"....4..\r..] [0x00 0x21 0x00 0x34 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x13 0x5c 0x00 0x00 0x02 0x3d 0xf1 0x0d 0xf9 0x7c 0xf5 0x]
1225489mS T1Line: line: 9.1: State= IncomingGuard RxMessage: ReceivedDigit
1225489mS T1Line: line: 9.1: Routing Digit Received 4
1225631mS T1DSP: PRIU DSP 3: read tone, port 0, channel 1, tone '3'
1225631mS T1Dialler: dialler: -258258720.1: Receive DTMF 3
1225631mS T1Channel: chan: E&M 9.1: StateChange WaitForDigits->Talk
1225632mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [.!.3.C%d.T-0.+.....\...=.\r.|.C%....3......"....3..\r..] [0x00 0x21 0x00 0x33 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x2b 0xa1 0x00 0xf5 0x11 0x13 0x5c 0x00 0x00 0x02 0x3d 0xf1 0x0d 0xf9 0x7c 0xf5 0x]
1225632mS T1Line: line: 9.1: State= IncomingGuard RxMessage: ReceivedDigit
1225632mS T1Line: line: 9.1: Routing Digit Received 3
1225632mS CMCallPkt: v=0
CMInformation
Line: type=T1Line 9 Call: lid=0 id=-1 in=0
Tag type=Binary flags=0x1 [...!.....T-0.\ra$.!.3.C%d.T-0.+.....\...=.\r.|.C%......] [0x00 0x07 0x00 0x21 0xf5 0x1d 0x1b 0xf4 0xf5 0x54 0x2d 0x30 0xf1 0x0d 0x61 0x24 0x00 0x21 0x00 0x33 0xf5 0x43 0x25 0x64 0xf5 0x54 0x2d 0x30 0xf0 0x]
1225632mS T1Line: line: 9.1: State= IncomingGuard RxMessage: Ringing
1225632mS T1Line: line: 9.1: State Change IncomingGuard -> Present
1225632mS T1Line: line: 9.1: Incoming Call from to 3143
1225633mS CMCallEvt: 0000000000000000 0.1131.0 -1 BaseEP: NEW CMEndpoint f171bc70 TOTAL NOW=1 CALL_LIST=0
1225633mS CMCallEvt: CREATE CALL:35 (f17219fc)
1225634mS CMCallEvt: 0000000000000000 0.1132.0 -1 BaseEP: NEW CMEndpoint f172513c TOTAL NOW=2 CALL_LIST=0
1225637mS CMLineRx: v=9
CMSetup
Line: type=T1Line 9 Call: lid=9 id=1131 in=1
Called[3143] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[] Type=Unknown Plan=Default Pres=NAInterworking (2)
BC: CMTC=Speech CMTM=CallIndSigCon CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=5 chan=2
IE CMIERespondingPartyNumber (230)(P:2 S:100 T:0 N:100 R:4) number=
IE CMIEDeviceDetail (231) ac112a0a0000046b LOCALE=enu HW=15 VER=11 class=CMDeviceT1Trunk type=0 number=9 channel=1 features=0x0 rx_gain=32 tx_gain=32
ep_callid=1131 ipaddr=172.17.42.10 apps=0 loc=0 em_a_loc=0 em_d_loc=0 features2=0x0 is_spcall=1 ignores_dtmf=0 avgsid=
1225637mS CMCallEvt: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: StateChange: END=A CMCSIdle->CMCSDialInitiated
1225637mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: LOOKUP CALL ROUTE: GID=0 type=0 called_party=3143 sub= calling= calling_sub= dir=in complete=1 ses=0
1225637mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: SET BESTMATCH: length 4 vs -1 match=3143 dest=3600
1225637mS CMCallEvt: Priority hike: call 35 priority 0->1
1225637mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: LOOKUP ICR: DDI= CGPN= (Destination 3600 ) => CDPN=3600
1225637mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: ADD TARGET (N): number=3600 type=0 depth=1 nobar=1 setorig=1 ses=0
1225638mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: SET USER: Extn3600office orig=1
1225638mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: ADD USER: Extn3600office depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeUnknown) incl(0x0) excpt(0x0), allow_redir(1) remote=00000000 simult 0 (0) r_lic=T
1225638mS CMCallEvt: 0000000000000000 0.1133.0 -1 BaseEP: NEW CMEndpoint f1745d38 TOTAL NOW=3 CALL_LIST=1
1225638mS CMCallEvt: 0000000000000000 0.1133.0 -1 Extn3600office.-1: NEW CMExtnEndpoint f1745d38, Name=Extn3600office, Extn=3600, Phys Extn=3600
1225640mS CMTARGET: ac112a0a0000046d 0.1133.0 35 Extn3600office.0: ADD PRIMARY
1225640mS CMTARGET: FoundKnownSystemTargets ICR cache hit
1225640mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: INITIAL TARGETING SUCCEEDED
1225641mS CMTARGET: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: GetNoAnswerTimer:15
1225641mS CMCallEvt: ac112a0a0000046b 9.1131.1 35 T1 Trunk:9 CHAN=1: StateChange: END=A CMCSDialInitiated->CMCSDialled
1225641mS CMLineTx: v=9
CMProceeding
Line: type=T1Line 9 Call: lid=9 id=1131 in=1
1225641mS T1Line: line: 9.1: State: Present CMMessage: CMProceeding
1225641mS T1Line: line: 9.1: State Change Present -> ICProceeding
1225642mS CMCallEvt: 0000000000000000 0.1132.0 35 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
1225643mS CMCallEvt: ac112a0a0000046d 0.1133.0 35 Extn3600office.0: StateChange: END=T CMCSIdle->CMCSOffering
1225643mS CMExtnEvt: Extn3600office: CMExtnHandler::SetCurrent( id: 0->1133 )
1225643mS CMExtnTx: v=3600, p1=0
CMSetup
Line: type=AnalogueExtn 5 Call: lid=0 id=1 in=0
Called[3600] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[] Type=Unknown Plan=Default Pres=NAInterworking (2)
BC: CMTC=Speech CMTM=CallIndSigCon CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=6 chan=25
IE CMIERespondingPartyNumber (230)(P:2 S:100 T:0 N:100 R:4) number=
IE CMIEDeviceDetail (231) ac112a0a0000046b LOCALE=enu HW=15 VER=11 class=CMDeviceT1Trunk type=0 number=9 channel=1 features=0x20 rx_gain=32 tx_gain=32
ep_callid=1131 ipaddr=172.17.42.10 apps=0 loc=0 em_a_loc=0 em_d_loc=0 features2=0x0 is_spcall=1 ignores_dtmf=0 avgsid=
IE CMIECalledPartyName (224)(Type=CMNameInternalUser) name=Extn3600office
IE CMIECalledPartyKName (225)(Type=CMNameDefault) name=3600 Office FAX 4064783143
IE CMIEIcrPriorityDetail (239) Priority = 1
IE CMIEMohSourceId (247) MOH Source = 1
UUI type=Local [......2Pd...] [0x01 0x01 0x00 0x00 0x01 0x02 0x32 0x50 0x64 0x00 0x00 0x00 ]
Display [External]
Timed: 26/08/19 10:21
Locale: enu
Any help is greatly appreciated!