SCN Single Call at a Time, MPLS VPN problem? 1

[waldrondigital]

Recently we moved from an IPSec Internet VPN to a Paetec-managed MPLS between our two offices and two separate IP500s. Since the change only one call is allowed between the two offices. Once someone has initiated a call on either side, any calls made while the first is one the line get a UNOBTAINABLE. I have 8 VCMs on each side and this was working fine with our previous IPSec VPN.

Here's my dump with AVRip. I just want to confirm that this is a line issue with Paetec's QoS/programming/configuration ... Can someone tell me if this is the case based on the dump?

Here's what I did in the following example:

called 8502 from 2135 and kept Maria on the line
called 8505 (Georgia) from 8563 and got UNOBTAINABLE

In the IP Line settings on both sides I have:
8 # of chans
8 outgoing
8 voice
0 data

I tried with 8 in data channels and no change in the symptoms.

448323mS AVRIP Tx: v=10.1.2.40 send=0 receive=0
PLATFORM: requiresvoicemail 0 operational 1 version 3 recordsupported 1
Platform Id 0 Version 4.2(11)
Name SHTG_ElSegundo
Codepage 2, Unicode UnicodeSupportOn
Time offset: 0

********** Warning: Logging to Screen Started **********
449315mS CMCallEvt: 0.1039.0 -1 BaseEP: NEW CMEndpoint f5677360 TOTAL NOW=3 CALL_LIST=1
449316mS CMCallEvt: CREATE CALL:13 (f561d924)
449316mS CMCallEvt: 0.1040.0 -1 BaseEP: NEW CMEndpoint f5675fa8 TOTAL NOW=4 CALL_LIST=1
449317mS CMExtnEvt: MichaelW: CMExtnHandler::SetCurrent( id: 0->1039 )
449318mS CMExtnRx: v=2135, p1=0
CMSetup
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[2135] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIECallingPartyName (110) MichaelW
IE CMIECallingPartyKName (226) Michael Waldron
449318mS CMCallEvt: 0.1039.0 13 MichaelW.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
449318mS CMExtnEvt: v=2 State, new=Connected old=Idle,0,0,MichaelW
449318mS SCN DHG LongestIdle: TriggerUpdateLII: extn(2135) state(1) idle_time(448018) mass_update (0)
449319mS SCN Ctrl Tx: VPNNetworkedPBX(10.1.2.40)::UpdateLII Unicode(2) TimeNow(449319)
449319mS SCN Ctrl Tx: extn(2135) state(1) idle_time(448018) mass_update(0)
449319mS CMTARGET: 0.1039.0 13 MichaelW.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=2135 dir=out complete=0 ses=0
449320mS CMTARGET: 0.1039.0 13 MichaelW.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
449320mS CMCallEvt: 0.1039.0 13 MichaelW.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
449320mS CMExtnEvt: v=2 State, new=Dialling old=Connected,0,0,MichaelW
449321mS CMExtnTx: v=2135, p1=0
CMSetupAck
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
BChan: slot=20 chan=2
Timed: 22/09/09 14:41
449321mS CD: CALL: 0.1039.0 BState=Idle Cut=1 Music=3.0 Aend="MichaelW(2135)" (20.2) Bend="" [] (0.0) CalledNum= () CallingNum=2135 (MichaelW) Internal=1 Time=6 AState=DialInitiated
449322mS CMMap: a=20.2 b=0.0 D1
449355mS RES: Tue 22/9/2009 14:41:20 FreeMem=75099704(1) CMMsg=6 (7) Buff=200 952 999 7414 5 Links=1271
449355mS RES2: RTEngine=0, CMRTEngine=0, Timer=56, Poll=0, Ready=0, CMReady=0, CMQueue=0, VPNNQueue=0
449967mS PRN: 2135: Digit Pressed 8
449967mS CMExtnRx: v=2135, p1=0
CMInformation
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
Called[8] Type=Default (100) Reason=CMDRdirect
449968mS CMTARGET: 0.1039.0 13 MichaelW.0: Setting Hard Timer 5000
449968mS CMTARGET: 0.1039.0 13 MichaelW.0: LOOKUP CALL ROUTE: type=100 called_party=8 sub= calling=2135 dir=out complete=0 ses=0
449968mS CMTARGET: 0.1039.0 13 MichaelW.0: ADD TARGET (N): number=8 type=100 depth=1 nobar=1 setorig=1 ses=0
449969mS CMMap: a=20.2 b=0.0 D0
450166mS PRN: 2135: Digit Pressed 5
450166mS CMExtnRx: v=2135, p1=0
CMInformation
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
Called[5] Type=Default (100) Reason=CMDRdirect
450167mS CMTARGET: 0.1039.0 13 MichaelW.0: Setting Hard Timer 5000
450167mS CMTARGET: 0.1039.0 13 MichaelW.0: LOOKUP CALL ROUTE: type=100 called_party=85 sub= calling=2135 dir=out complete=0 ses=0
450167mS CMTARGET: 0.1039.0 13 MichaelW.0: ADD TARGET (N): number=85 type=100 depth=1 nobar=1 setorig=1 ses=0
450391mS PRN: 2135: Digit Pressed 0
450391mS CMExtnRx: v=2135, p1=0
CMInformation
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
Called[0] Type=Default (100) Reason=CMDRdirect
450391mS CMTARGET: 0.1039.0 13 MichaelW.0: Setting Hard Timer 5000
450392mS CMTARGET: 0.1039.0 13 MichaelW.0: LOOKUP CALL ROUTE: type=100 called_party=850 sub= calling=2135 dir=out complete=0 ses=0
450392mS CMTARGET: 0.1039.0 13 MichaelW.0: ADD TARGET (N): number=850 type=100 depth=1 nobar=1 setorig=1 ses=0
450879mS PRN: 2135: Digit Pressed 2
450879mS CMExtnRx: v=2135, p1=0
CMInformation
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
Called[2] Type=Default (100) Reason=CMDRdirect
450879mS CMTARGET: 0.1039.0 13 MichaelW.0: Setting Hard Timer 5000
450880mS CMTARGET: 0.1039.0 13 MichaelW.0: LOOKUP CALL ROUTE: type=100 called_party=8502 sub= calling=2135 dir=out complete=0 ses=0
450880mS CMTARGET: 0.1039.0 13 MichaelW.0: ADD TARGET (N): number=8502 type=100 depth=1 nobar=1 setorig=1 ses=0
450880mS CMTARGET: 0.1039.0 13 MichaelW.0: SET USER: MariaM orig=1
450880mS CMTARGET: 0.1039.0 13 MichaelW.0: ADD USER: MariaM depth=2 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeDefault) incl(0x0) excpt(0x0), allow_redir(0) remote=0a010228
450881mS CMTARGET: 0.1039.0 13 MichaelW.0: Direct to Remote Target: MariaM
450881mS SCN USER: MakeCallToNetworkedPBX: pass=0 type=5 ipad=10.1.2.40 gid=31
450881mS CMMap: a=6.1 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder resource busy 1, total 8
450882mS CMCallEvt: 0.1041.0 -1 BaseEP: NEW CMEndpoint f563b3dc TOTAL NOW=5 CALL_LIST=2
450882mS PRN: Created MH f563b2d0 parent 0.1041.0 -1 H323TrunkEP
450887mS CMTARGET: MakeCallToNetworkedPBX using line group id: 31
450887mS CMTARGET: 0.1039.0 13 MichaelW.0: Targeted OK: MariaM
450887mS CMTARGET: 0.1039.0 13 MichaelW.0: CancelTimer CMTCDelayedProcessing
450887mS CMTARGET: 0.1039.0 13 MichaelW.0: INITIAL TARGETING SUCCEEDED
450888mS CMTARGET: 0.1039.0 13 MichaelW.0: GetNoAnswerTimer:18
450888mS CMCallEvt: 0.1039.0 13 MichaelW.0: StateChange: END=A CMCSDialling->CMCSDialled
450888mS CMExtnEvt: v=2 State, new=Proceeding old=Dialling,0,0,MichaelW
450888mS CMExtnTx: v=2135, p1=0
CMProceeding
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
Timed: 22/09/09 14:41
450889mS CMCallEvt: 0.1040.0 13 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
450890mS CMCallEvt: 0.1041.0 13 H323TrunkEP: StateChange: END=T CMCSIdle->CMCSOffering
450891mS CMLineTx: v=30
CMSetup
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
Called[8502] Type=Default (100) Reason=CMDRdirect SndComp Calling[2135] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=20 chan=2
IE CMIERespondingPartyName (228) MichaelW
IE CMIERespondingPartyKName (229) Michael Waldron
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:4) number=2135
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceStdPhone type=27 number=2 channel=0 rx_gain=32 tx_gain=32 ep_callid=1039 ipaddr=10.0.40.1 apps=0
IE CMIECalledPartyName (224) MariaM
IE CMIECalledPartyKName (225) Maria Mak
IE CMIECallingPartyName (110) MichaelW
IE CMIECallingPartyKName (226) Michael Waldron
IE CMIEMohSourceId (247) MOH Source = 255
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
CallingName.Invoke.CodePageUtf8String
invokeId 14633
user 'MichaelW' presentation Allowed
IE CMIEFastStartInfoData (6)
IE CMIECallSignalChannelData (8) unknown
Timed: 22/09/09 14:41
Locale: enu
450893mS CD: CALL: 0.1039.0 BState=Idle Cut=1 Music=0.0 Aend="MichaelW(2135)" (20.2) Bend="MariaM(8502)" [Line 30] (0.0) CalledNum=8502 (MariaM) CallingNum=2135 (MichaelW) Internal=0 Time=1578 AState=Dialled
450895mS H323Evt: v=0 stacknum=30 State, new=NullState, old=NullState id=-1
450899mS H323Evt: v=0 stacknum=30 State, new=Initiated, old=NullState id=1041
450937mS SCN Ctrl Rx: VPNNetworkedPBX(10.1.2.40)::ReadLII len(24) Unicode(2)
450937mS SCN Ctrl Rx: extn(8502) state(1) idle_time(313756) mass_update(0)
450937mS SCN DHG LongestIdle: TriggerUpdateLII: extn(8502) state(1) idle_time(313756) mass_update (0)
450942mS H323Evt: v=0 stacknum=30 State, new=Proceeding, old=Initiated id=1041
450943mS CMLineRx: v=30
CMProceeding
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
450943mS CMCallEvt: 0.1040.0 13 TargetingEP: RequestEnd 0.1041.0 13 H323TrunkEP
450943mS CMTARGET: 0.1039.0 13 MichaelW.0: CancelTimer CMTCNoAnswerTimeout
450944mS CMCallEvt: 0.1040.0 -1 BaseEP: DELETE CMEndpoint f5675fa8 TOTAL NOW=4 CALL_LIST=2
450944mS CMCallEvt: 0.1041.0 13 H323TrunkEP: StateChange: END=B CMCSOffering->CMCSAccept
450946mS CD: CALL: 0.1039.0 BState=Ringing Cut=3 Music=0.0 Aend="MichaelW(2135)" (20.2) Bend="MariaM(8502)" [Line 30] (280.1) CalledNum=8502 (MariaM) CallingNum=2135 (MichaelW) Internal=0 Time=1631 AState=Dialled
450955mS H323Evt: v=0 stacknum=30 State, new=Delivered, old=Proceeding id=1041
450957mS CMLineRx: v=30
CMAlerting
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
AlertingName.Invoke.CodePageISO8859-1
invokeId 14629
user 'MariaM' presentation Allowed
IE CMIERespondingPartyName (228) MariaM
IE CMIERespondingPartyKName (229) Maria Mak
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:4) number=8502
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceStdPhone type=26 number=6 channel=0 rx_gain=32 tx_gain=32 ep_callid=1029 ipaddr=10.1.2.40 apps=0
IE CMIEFastStartInfoData (6)
450958mS CMCallEvt: 0.1041.0 13 H323TrunkEP: StateChange: END=B CMCSAccept->CMCSRinging
450958mS CMCallEvt: 0.1039.0 13 MichaelW.0: StateChange: END=A CMCSDialled->CMCSRingBack
450959mS CMExtnEvt: v=2 State, new=Alerting old=Proceeding,0,0,MichaelW
450961mS CMExtnTx: v=2135, p1=0
CMAlerting
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
AlertingName.Invoke.CodePageISO8859-1
invokeId 14629
user 'MariaM' presentation Allowed
IE CMIERespondingPartyName (228) MariaM
IE CMIERespondingPartyKName (229) Maria Mak
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:4) number=8502
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceStdPhone type=26 number=6 channel=0 rx_gain=32 tx_gain=32 ep_callid=1029 ipaddr=10.1.2.40 apps=0
IE CMIEFastStartInfoData (6)
Timed: 22/09/09 14:41
450962mS CD: CALL: 0.1039.0 BState=Ringing Cut=3 Music=0.0 Aend="MichaelW(2135)" (20.2) Bend="MariaM(8502)" [Line 30] (280.1) CalledNum=8502 (MariaM) CallingNum=2135 (MichaelW) Internal=0 Time=1647 AState=Ringing
450963mS CMMap: PCG::MapBChan pcp[126]b1r0 cp_b f56e49b8 other_cp_b 0 type CGTypeSimple
450964mS CMMap: a=20.2 b=0.0 PCGS CPReserveCodec (pcp[146]b0r1) true
450964mS CMMap: PCG::MapBChan pcp[146]b0r1 cp_b f5a1ccb0 other_cp_b f56e49b8 type CGTypeSimple
450964mS CMMap: a=20.2 b=6.1 M1
451951mS H323Evt: RTP(50r): 10.0.40.1/49152 10.1.2.40/49152 CODEC 6 PKTSZ=20 RFC2833=off AGE=988 SENT 6 (avg size=2) RECV 50 (avg size=20)
453760mS H323Evt: v=0 stacknum=30 State, new=Active, old=Delivered id=1041
453763mS CMLineRx: v=30
CMConnect
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
ConnectedName.Invoke.CodePageISO8859-1
invokeId 14630
user 'MariaM' presentation Allowed
IE CMIERespondingPartyName (228) MariaM
IE CMIERespondingPartyKName (229) Maria Mak
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:4) number=8502
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceStdPhone type=26 number=6 channel=0 rx_gain=32 tx_gain=32 ep_callid=1029 ipaddr=10.1.2.40 apps=0
IE CMIEPrimitiveData (7)
453764mS CMCallEvt: 0.1041.0 13 H323TrunkEP: StateChange: END=B CMCSRinging->CMCSConnReq
453764mS CMCallEvt: 0.1039.0 13 MichaelW.0: StateChange: END=A CMCSRingBack->CMCSOGConnReq
453764mS CMExtnEvt: v=2 State, new=Connected old=Alerting,0,0,MichaelW
453766mS CMLineTx: v=30
CMFacility
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
IE CMIEPrimitiveData (7)
453767mS CMExtnTx: v=2135, p1=0
CMConnect
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
ConnectedName.Invoke.CodePageISO8859-1
invokeId 14630
user 'MariaM' presentation Allowed
IE CMIERespondingPartyName (228) MariaM
IE CMIERespondingPartyKName (229) Maria Mak
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:4) number=8502
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceStdPhone type=26 number=6 channel=0 rx_gain=32 tx_gain=32 ep_callid=1029 ipaddr=10.1.2.40 apps=0
Timed: 22/09/09 14:41
453767mS CMExtnRx: v=2135, p1=0
CMConnectAck
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
453767mS CMCallEvt: 0.1039.0 13 MichaelW.0: StateChange: END=A CMCSOGConnReq->CMCSConnected
453767mS CMTARGET: 0.1039.0 13 MichaelW.0: ~CMTargetHandler
453769mS CMCallEvt: 0.1041.0 13 H323TrunkEP: StateChange: END=B CMCSConnReq->CMCSConnected
453771mS CMLineTx: v=30
CMConnectAck
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
BChan: slot=20 chan=2
IE CMIERespondingPartyName (228) MichaelW
IE CMIERespondingPartyKName (229) Michael Waldron
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:4) number=2135
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceStdPhone type=27 number=2 channel=0 rx_gain=32 tx_gain=32 ep_callid=1039 ipaddr=10.0.40.1 apps=0
453773mS CD: CALL: 0.1039.0 BState=Connected Cut=3 Music=0.0 Aend="MichaelW(2135)" (20.2) Bend="MariaM(8502)" [Line 30] (280.1) CalledNum=8502 (MariaM) CallingNum=2135 (MichaelW) Internal=0 Time=4457 AState=Connected
453795mS CMLineRx: v=30
CMFacility
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
IE CMIEPrimitiveData (7)
453796mS CMExtnTx: v=2135, p1=0
CMFacility
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
Timed: 22/09/09 14:41
453797mS CD: CALL: 0.1039.0 BState=Connected Cut=3 Music=0.0 Aend="MichaelW(2135)" (20.2) Bend="MariaM(8502)" [Line 30] (280.1) CalledNum=8502 (MariaM) CallingNum=2135 (MichaelW) Internal=0 Time=4481 AState=Connected
453807mS CMLineRx: v=30
CMFacility
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
IE CMIEPrimitiveData (7)
453808mS CMExtnTx: v=2135, p1=0
CMFacility
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
Timed: 22/09/09 14:41
453809mS CD: CALL: 0.1039.0 BState=Connected Cut=3 Music=0.0 Aend="MichaelW(2135)" (20.2) Bend="MariaM(8502)" [Line 30] (280.1) CalledNum=8502 (MariaM) CallingNum=2135 (MichaelW) Internal=0 Time=4493 AState=Connected
454355mS RES: Tue 22/9/2009 14:41:25 FreeMem=75084252(1) CMMsg=6 (7) Buff=200 952 999 7414 5 Links=1186
454355mS RES2: RTEngine=0, CMRTEngine=0, Timer=60, Poll=0, Ready=0, CMReady=0, CMQueue=0, VPNNQueue=0
457954mS AVRIP Rx: v=10.1.2.40 send=0 receive=0
458323mS PRN: VPNN: SendRIP to pbx 10.1.2.40
458323mS AVRIP Tx: v=10.1.2.40 send=0 receive=1
PLATFORM: requiresvoicemail 0 operational 1 version 3 recordsupported 1
Platform Id 0 Version 4.2(11)
Name SHTG_ElSegundo
Codepage 2, Unicode UnicodeSupportOn
Time offset: 0
462113mS CMCallEvt: 0.1042.0 -1 BaseEP: NEW CMEndpoint f561dcf8 TOTAL NOW=5 CALL_LIST=2
462114mS CMCallEvt: CREATE CALL:14 (f56063f8)
462114mS CMCallEvt: 0.1043.0 -1 BaseEP: NEW CMEndpoint f5675fa8 TOTAL NOW=6 CALL_LIST=2
462116mS CMExtnEvt: DougB: CMExtnHandler::SetCurrent( id: 0->1042 )
462116mS CMExtnRx: v=8563, p1=0
CMSetup
Line: type=DigitalExtn 3 Call: lid=0 id=1042 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[8563] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIECallingPartyName (110) DougB
IE CMIECallingPartyKName (226) Doug Brown
462116mS CMCallEvt: 0.1042.0 14 DougB.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
462117mS CMExtnEvt: v=1 State, new=Connected old=Idle,0,0,DougB
462117mS SCN DHG LongestIdle: TriggerUpdateLII: extn(8563) state(1) idle_time(306742) mass_update (0)
462117mS SCN Ctrl Tx: VPNNetworkedPBX(10.1.2.40)::UpdateLII Unicode(2) TimeNow(462117)
462117mS SCN Ctrl Tx: extn(8563) state(1) idle_time(306742) mass_update(0)
462118mS CMTARGET: 0.1042.0 14 DougB.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=8563 dir=out complete=0 ses=0
462118mS CMTARGET: 0.1042.0 14 DougB.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
462119mS CMCallEvt: 0.1042.0 14 DougB.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
462119mS CMExtnEvt: v=1 State, new=Dialling old=Connected,0,0,DougB
462119mS CMExtnTx: v=8563, p1=0
CMSetupAck
Line: type=DigitalExtn 3 Call: lid=0 id=1042 in=0
BChan: slot=20 chan=9
Timed: 22/09/09 14:41
462120mS CD: CALL: 0.1042.0 BState=Idle Cut=1 Music=3.0 Aend="DougB(8563)" (20.9) Bend="" [] (0.0) CalledNum= () CallingNum=8563 (DougB) Internal=1 Time=6 AState=DialInitiated
462121mS CMMap: a=20.9 b=0.0 D1
462355mS RES: Tue 22/9/2009 14:41:33 FreeMem=75065016(1) CMMsg=6 (7) Buff=200 952 999 7414 5 Links=1178
462355mS RES2: RTEngine=0, CMRTEngine=0, Timer=61, Poll=0, Ready=0, CMReady=0, CMQueue=0, VPNNQueue=0
462464mS PRN: 8563: Digit Pressed 8
462464mS CMExtnRx: v=8563, p1=0
CMInformation
Line: type=DigitalExtn 3 Call: lid=0 id=1042 in=0
Called[8] Type=Default (100) Reason=CMDRdirect
462465mS CMTARGET: 0.1042.0 14 DougB.0: Setting Hard Timer 5000
462465mS CMTARGET: 0.1042.0 14 DougB.0: LOOKUP CALL ROUTE: type=100 called_party=8 sub= calling=8563 dir=out complete=0 ses=0
462465mS CMTARGET: 0.1042.0 14 DougB.0: ADD TARGET (N): number=8 type=100 depth=1 nobar=1 setorig=1 ses=0
462466mS CMMap: a=20.9 b=0.0 D0
462664mS PRN: 8563: Digit Pressed 5
462664mS CMExtnRx: v=8563, p1=0
CMInformation
Line: type=DigitalExtn 3 Call: lid=0 id=1042 in=0
Called[5] Type=Default (100) Reason=CMDRdirect
462665mS CMTARGET: 0.1042.0 14 DougB.0: Setting Hard Timer 5000
462665mS CMTARGET: 0.1042.0 14 DougB.0: LOOKUP CALL ROUTE: type=100 called_party=85 sub= calling=8563 dir=out complete=0 ses=0
462665mS CMTARGET: 0.1042.0 14 DougB.0: ADD TARGET (N): number=85 type=100 depth=1 nobar=1 setorig=1 ses=0
462863mS PRN: 8563: Digit Pressed 0
462863mS CMExtnRx: v=8563, p1=0
CMInformation
Line: type=DigitalExtn 3 Call: lid=0 id=1042 in=0
Called[0] Type=Default (100) Reason=CMDRdirect
462864mS CMTARGET: 0.1042.0 14 DougB.0: Setting Hard Timer 5000
462864mS CMTARGET: 0.1042.0 14 DougB.0: LOOKUP CALL ROUTE: type=100 called_party=850 sub= calling=8563 dir=out complete=0 ses=0
462864mS CMTARGET: 0.1042.0 14 DougB.0: ADD TARGET (N): number=850 type=100 depth=1 nobar=1 setorig=1 ses=0
463078mS PRN: 8563: Digit Pressed 5
463078mS CMExtnRx: v=8563, p1=0
CMInformation
Line: type=DigitalExtn 3 Call: lid=0 id=1042 in=0
Called[5] Type=Default (100) Reason=CMDRdirect
463079mS CMTARGET: 0.1042.0 14 DougB.0: Setting Hard Timer 5000
463079mS CMTARGET: 0.1042.0 14 DougB.0: LOOKUP CALL ROUTE: type=100 called_party=8505 sub= calling=8563 dir=out complete=0 ses=0
463079mS CMTARGET: 0.1042.0 14 DougB.0: ADD TARGET (N): number=8505 type=100 depth=1 nobar=1 setorig=1 ses=0
463079mS CMTARGET: 0.1042.0 14 DougB.0: SET USER: GeorgiaG orig=1
463079mS CMTARGET: 0.1042.0 14 DougB.0: ADD USER: GeorgiaG depth=2 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeDefault) incl(0x0) excpt(0x0), allow_redir(0) remote=0a010228
463080mS CMTARGET: 0.1042.0 14 DougB.0: Direct to Remote Target: GeorgiaG
463080mS SCN USER: MakeCallToNetworkedPBX: pass=0 type=5 ipad=10.1.2.40 gid=31
463080mS CMMap: a=6.17 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder resource busy 2, total 8
463081mS CMCallEvt: 0.1044.0 -1 BaseEP: NEW CMEndpoint f561ba74 TOTAL NOW=7 CALL_LIST=3
463081mS PRN: Created MH f561b968 parent 0.1044.0 -1 H323TrunkEP
463086mS CMTARGET: MakeCallToNetworkedPBX using line group id: 31
463087mS CMTARGET: 0.1042.0 14 DougB.0: Targeted OK: GeorgiaG
463087mS CMTARGET: 0.1042.0 14 DougB.0: CancelTimer CMTCDelayedProcessing
463087mS CMTARGET: 0.1042.0 14 DougB.0: INITIAL TARGETING SUCCEEDED
463087mS CMTARGET: 0.1042.0 14 DougB.0: GetNoAnswerTimer:18
463087mS CMCallEvt: 0.1042.0 14 DougB.0: StateChange: END=A CMCSDialling->CMCSDialled
463088mS CMExtnEvt: v=1 State, new=Proceeding old=Dialling,0,0,DougB
463088mS CMExtnTx: v=8563, p1=0
CMProceeding
Line: type=DigitalExtn 3 Call: lid=0 id=1042 in=0
Timed: 22/09/09 14:41
463088mS CMCallEvt: 0.1043.0 14 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
463089mS CMCallEvt: 0.1044.0 14 H323TrunkEP: StateChange: END=T CMCSIdle->CMCSOffering
463091mS CMLineTx: v=30
CMSetup
Line: type=IPLine 30 Call: lid=0 id=1044 in=0
Called[8505] Type=Default (100) Reason=CMDRdirect SndComp Calling[8563] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=20 chan=9
IE CMIERespondingPartyName (228) DougB
IE CMIERespondingPartyKName (229) Doug Brown
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:4) number=8563
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceStdPhone type=27 number=25 channel=0 rx_gain=32 tx_gain=32 ep_callid=1042 ipaddr=10.0.40.1 apps=0
IE CMIECalledPartyName (224) GeorgiaG
IE CMIECalledPartyKName (225) Georgia Goodman
IE CMIECallingPartyName (110) DougB
IE CMIECallingPartyKName (226) Doug Brown
IE CMIEMohSourceId (247) MOH Source = 255
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
CallingName.Invoke.CodePageUtf8String
invokeId 14634
user 'DougB' presentation Allowed
IE CMIEFastStartInfoData (6)
IE CMIECallSignalChannelData (8) unknown
Timed: 22/09/09 14:41
Locale: enu
463092mS CD: CALL: 0.1042.0 BState=Idle Cut=1 Music=0.0 Aend="DougB(8563)" (20.9) Bend="GeorgiaG(8505)" [Line 30] (0.0) CalledNum=8505 (GeorgiaG) CallingNum=8563 (DougB) Internal=0 Time=978 AState=Dialled
463094mS H323Evt: v=0 stacknum=30 State, new=NullState, old=NullState id=-1
463098mS H323Evt: v=0 stacknum=30 State, new=Initiated, old=NullState id=1044
463139mS H323Evt: v=0 stacknum=30 State, new=NullState, old=Initiated id=1044
463140mS CMLineRx: v=30
CMReleaseComp
Line: type=IPLine 30 Call: lid=0 id=1044 in=0
Cause=34, No cct/chan available
463140mS CMCallEvt: 0.1043.0 14 TargetingEP: RequestEnd 0.1044.0 14 H323TrunkEP
463141mS CMTARGET: 0.1042.0 14 DougB.0: CancelTimer CMTCNoAnswerTimeout
463141mS CMCallEvt: 0.1043.0 -1 BaseEP: DELETE CMEndpoint f5675fa8 TOTAL NOW=6 CALL_LIST=3
463142mS CMCallEvt: 0.1044.0 14 H323TrunkEP: StateChange: END=B CMCSOffering->CMCSCompleted
463144mS CMLOGGING: CALL:2009/09/2214:41,00:00:00,000,8563,O,8505,8505,DougB,,,0,,""n/a,0
463145mS CD: CALL: 0.1042.0 BState=Disconnecting Cut=1 Music=0.0 Aend="DougB(8563)" (20.9) Bend="GeorgiaG(8505)" [Line 30] (280.2) CalledNum=8505 (GeorgiaG) CallingNum=8563 (DougB) Internal=0 Time=1031 AState=Dialled
463145mS CD: CALL: 0.1042.0 Deleted
463146mS CMExtnEvt: DougB: CALL LOST (CMCauseNoChannel)
463146mS CMExtnEvt: DougB: Extn(8563) Calling Party Number(8563) Type(CMNTypeInternal)
463146mS CMCallEvt: 0.1042.0 -1 DougB.0: StateChange: END=X CMCSDialled->CMCSCompletedTone
463146mS CMExtnEvt: v=1 State, new=CMESCompleted old=Proceeding,0,0,DougB
463147mS CMCallEvt: 0.1044.0 -1 H323TrunkEP: StateChange: END=X CMCSCompleted->CMCSDelete
463147mS CMCallEvt: END CALL:14 (f56063f8)
463149mS PRN: Destroyed MH f561b968 parent unknown
463149mS CMCallEvt: 0.1044.0 -1 BaseEP: DELETE CMEndpoint f561ba74 TOTAL NOW=5 CALL_LIST=2
463151mS CMMap: a=6.17 b=0.0 Mapper::FreeCodec freed CMRTVocoder resource busy 1, total 8
463152mS CMMap: a=20.9 b=0.0 B2
463402mS CMMap: a=20.9 b=0.0 B0
463652mS CMMap: a=20.9 b=0.0 B2
463902mS CMMap: a=20.9 b=0.0 B0
464152mS CMMap: a=20.9 b=0.0 B2
464250mS CMExtnRx: v=8563, p1=0
CMReleaseComp
Line: type=DigitalExtn 3 Call: lid=0 id=1042 in=0
464250mS CMCallEvt: 0.1042.0 -1 DougB.0: StateChange: END=X CMCSCompletedTone->CMCSCompleted
464251mS CMExtnEvt: DougB: CALL LOST (CMCauseForceClear)
464251mS CMExtnEvt: DougB: Extn(8563) Calling Party Number(8563) Type(CMNTypeInternal)
464251mS CMExtnEvt: DougB: CMExtnHandler::SetCurrent( id: 1042->0 )
464251mS CMCallEvt: 0.1042.0 -1 DougB.-1: StateChange: END=X CMCSCompleted->CMCSDelete
464251mS CMExtnEvt: v=1 State, new=PortRecoverDelay old=CMESCompleted,0,0,DougB
464252mS CMTARGET: 0.1042.0 -1 BaseEP: ~CMTargetHandler
464252mS CMCallEvt: 0.1042.0 -1 BaseEP: DELETE CMEndpoint f561dcf8 TOTAL NOW=4 CALL_LIST=2
464253mS CMMap: a=20.9 b=0.0 B0
466251mS CMExtnEvt: DougB: Recover Timer reason=CMTRWrapUp
466251mS CMExtnEvt: v=1 State, new=Idle old=PortRecoverDelay,0,0,DougB
466251mS SCN DHG LongestIdle: TriggerUpdateLII: extn(8563) state(0) idle_time(466251) mass_update (0)
466251mS SCN Ctrl Tx: VPNNetworkedPBX(10.1.2.40)::UpdateLII Unicode(2) TimeNow(466251)
466252mS SCN Ctrl Tx: extn(8563) state(0) idle_time(466251) mass_update(0)
466252mS CMExtnTx: v=8563, p1=0
CMVoiceMailStatus
Line: type=DigitalExtn 3 Call: lid=0 id=-1 in=0
Called[DougB Msgs=0 Old=0 Sav=0] Type=Default (100) Reason=CMDRdirect Calling[00000000] Type=Default Plan=Default
Display [DougB Msgs=0]
Timed: 22/09/09 14:41
467954mS AVRIP Rx: v=10.1.2.40 send=0 receive=0
468323mS PRN: VPNN: SendRIP to pbx 10.1.2.40
468323mS AVRIP Tx: v=10.1.2.40 send=0 receive=1
PLATFORM: requiresvoicemail 0 operational 1 version 3 recordsupported 1
Platform Id 0 Version 4.2(11)
Name SHTG_ElSegundo
Codepage 2, Unicode UnicodeSupportOn
Time offset: 0
468355mS RES: Tue 22/9/2009 14:41:39 FreeMem=75083848(1) CMMsg=6 (7) Buff=200 952 1000 7414 5 Links=1184
468355mS RES2: RTEngine=0, CMRTEngine=0, Timer=59, Poll=0, Ready=0, CMReady=0, CMQueue=0, VPNNQueue=0
469405mS CMExtnRx: v=2135, p1=0
CMReleaseComp
Line: type=DigitalExtn 2 Call: lid=0 id=1039 in=0
469405mS CMCallEvt: 0.1039.0 13 MichaelW.0: StateChange: END=A CMCSConnected->CMCSCompleted
469407mS CMLineTx: v=30
CMFacility
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
IE CMIEFastStartInfoData (6)
469407mS CMExtnEvt: v=2 State, new=CMESCompleted old=Connected,0,0,MichaelW
469409mS CMLOGGING: CALL:2009/09/2214:41,00:00:15,002,2135,O,8502,8502,MichaelW,,,0,,""n/a,0
469409mS CD: CALL: 0.1039.0 BState=Connected Cut=2 Music=0.0 Aend="MichaelW(2135)" (20.2) Bend="MariaM(8502)" [Line 30] (280.1) CalledNum=8502 (MariaM) CallingNum=2135 (MichaelW) Internal=0 Time=20094 AState=Idle
469410mS CD: CALL: 0.1039.0 Deleted
469410mS CMExtnEvt: MichaelW: CALL LOST (CMCauseNormal)
469410mS CMExtnEvt: MichaelW: Extn(2135) Calling Party Number(2135) Type(CMNTypeInternal)
469410mS CMExtnEvt: MichaelW: CMExtnHandler::SetCurrent( id: 1039->0 )
469411mS CMCallEvt: 0.1039.0 -1 MichaelW.-1: StateChange: END=X CMCSCompleted->CMCSDelete
469411mS CMExtnEvt: v=2 State, new=PortRecoverDelay old=CMESCompleted,0,0,MichaelW
469413mS CMLineTx: v=30
CMReleaseComp
Line: type=IPLine 30 Call: lid=0 id=1041 in=0
Cause=16, Normal call clearing
469413mS CMCallEvt: 0.1041.0 -1 H323TrunkEP: StateChange: END=X CMCSConnected->CMCSDelete
469414mS PRN: Destroyed MH f563b2d0 parent unknown
469415mS CMCallEvt: 0.1041.0 -1 BaseEP: DELETE CMEndpoint f563b3dc TOTAL NOW=3 CALL_LIST=1
469415mS CMCallEvt: END CALL:13 (f561d924)
469416mS CMCallEvt: 0.1039.0 -1 BaseEP: DELETE CMEndpoint f5677360 TOTAL NOW=2 CALL_LIST=1
469417mS CMMap: PCG::UnmapBChan pcp[126]b1r0 cp_b f56e49b8 other_cp_b f5a1ccb0
469417mS CMMap: a=6.1 b=20.2 M0
469417mS CMMap: PCG::UnmapBChan pcp[146]b0r1 cp_b 0 other_cp_b 0
469417mS H323Evt: RTP(END): 10.0.40.1/49152 10.1.2.40/49152 CODEC 6 PKTSZ=20 RFC2833=off AGE=18454 SENT 517 RECV 681 RTdelay=0 jitter=0 loss=256 remotejitter=0 remoteloss=0
469418mS CMMap: a=6.1 b=0.0 Mapper::FreeCodec freed CMRTVocoder resource busy 1, total 8
469420mS H323Evt: v=0 stacknum=30 State, new=ReleaseReq, old=Active id=1041
469421mS H323Evt: v=0 stacknum=30 State, new=NullState, old=ReleaseReq id=1041
471411mS CMExtnEvt: MichaelW: Recover Timer reason=CMTRWrapUp



Many many thanks!

 

[amriddle01]

463146mS CMExtnEvt: DougB: CALL LOST (CMCauseNoChannel)
It would appear the system is unable to bring up a second channel for the call despite this entry
463080mS CMMap: a=6.17 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder resource busy 2, total 8

which means you have sufficiant VCM resources, I would say it's the new link at fault :-0

ACS - IP Office Implement

"What the Crocodile Hat....was that?

 

[waldrondigital]

Paetec of course says "Customer CPE" ticket closed... errrrgghhh

Any way I can disprove them?? I guess I can bring the IPSec VPN back up and try it that way, if it works I guess I can pin it on them. They are willing to work with me, but in this day and age people just point the finger and say FU.

What do "data" channels in the IP Line setup do anyway?

 

[waldrondigital]

Well I tried making this work on our existing VPN (which used to work!) and it still does the same thing. So this is not a Paetec problem like they said. It's CPE!

I have no idea where to start here as I CAN make one call at a time, just not more. Could this be a defective or malfunctioning VCM32? A configuration entry that I missed?

Now that I've had a chance to test in on both sides of the equation here are my observations:

If we tie up one call between the offices then attempt a second call:
1. You call from Site A to HQ and get NUMBER BUSY
or you get the voicemail asking if you want to leave
yourself a message... very weird.

2. You call from HQ to Site A and get NUMBER BUSY
or get UNOBTAINABLE (most common)

I have deleted and re-created our IP Line with a different ID, same issue.

I really don't want to call our phone vendor because they are inglorious basterds.

Thanks.

 

[amriddle01]

Try putting all channels to 8 so voice 8 data 8 incoming 8 etc then reboot, same both sides

ACS - IP Office Implement

"What the Crocodile Hat....was that?

 

[waldrondigital]

Another observation - I get insufficient VCMs at Site A but not Site B. They have the same amount of VCMs at each. I'm thinking the problem is on the Site A side as there are no errors on the HQ side.

This is very frustrating!

I'm going to try deleting our +4 VCM license at Site A and readding it and see if that does anything.

 

[waldrondigital]

Thanks amriddle, I tried every combo of #s in there (originally it was all 20s and that worked).

I think it's some sort of VCM failure at Site A. I'm waiting for a reboot now after doing the license dance

 

[waldrondigital]

No love on the license readd... I'm out of ideas

 

[amriddle01]

What handsets do they have? If IP and you allow direct media path and still only one call is succesfull it's not the VCM as that will be getting used once it's connected

ACS - IP Office Implement

"What the Crocodile Hat....was that?

 

[amriddle01]

not be used that should say

ACS - IP Office Implement

"What the Crocodile Hat....was that?

 

[waldrondigital]

Relented and called the vendor, we both agree config is fine, licensing is okay... We're both thinking VCM issue at Site A.

amriddle thank you! Here's a star for helping!

 

[tlpeter]

It coud be a codec mismatch issue !

Run SSA and let it log continuous so you can pinpoint the moment it goes wrong
Then you can see the amount of simultaneous calls and the codec used
Als you see the vcm usage




ACS - Implement IP Office
ACA - Implement IP Telephony -- ACA - Design IP Telephony
ACA - Voice Services Management
______________
Women and cats can do as they please and men and dogs should relax and get used to the idea!

 

[amriddle01]

No problems, hope you get it working, could be codec but then that would normally just hold the VCM channel open but you have 7 more so another call should still work (in theory) but it's worth looking at

ACS - IP Office Implement

"What the Crocodile Hat....was that?

 

[waldrondigital]

The problem was a VCM at Site A that went bad. A hardware replacement under warranty fixed it.

So it wasn't:
licensing
programming

Go figure

 

[waldrondigital]

This problem occured more than once, and I opened a separate thread regarding a bad batch of VCM32s

http://www.tek-tips.com/viewthread.cfm?qid=1578638&page=1