Avaya IP Office 8.1 and E1 Sim Box LCR (GSM to E1 modem)

[skaval24]

Have connected our Avaya PABX to a sim box (GSM to E1 gateway) using line signalling as CO, CPE gives out of service status.. The E1 has come up (idle status) however we are unable to make calls. The guys setting up the sim box can see the DDI of the extension coming in but the dialed digits are apparently not showing hence the Gateway sending a disconnect. Below is the trace;

3214558mS PRN: 4320: Digit Pressed 7
3214560mS CMCallEvt: 0.1060.0 -1 BaseEP: NEW CMEndpoint f4940560 TOTAL NOW=1 CALL_LIST=0
3214560mS CMCallEvt: 0.1060.0 -1 Neo Sethibe.-1: NEW CMExtnEndpoint f4940560, Name=Neo Sethibe, Extn=4320, Phys Extn=4320
3214561mS CMCallEvt: CREATE CALL:23 (f4ae4650)
3214561mS CMCallEvt: 0.1061.0 -1 BaseEP: NEW CMEndpoint f4ae3188 TOTAL NOW=2 CALL_LIST=0
3214563mS CMExtnEvt: Neo Sethibe: CMExtnHandler::SetCurrent( id: 0->1060 )
3214564mS CMExtnRx: v=4320, p1=0
CMSetup
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[4320] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ALaw
IE CMIEFastStartInfoData (6) 10 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Neo Sethibe
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=Neo Sethibe
3214564mS CMCallEvt: 321.1060.0 23 Neo Sethibe.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
3214564mS CMExtnEvt: v=66 State, new=Dialling old=Idle,0,0,Neo Sethibe
3214565mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=4320 dir=out complete=0 ses=0
3214565mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
3214566mS CMCallEvt: 321.1060.0 23 Neo Sethibe.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
3214568mS CMExtnTx: v=4320, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIESecurityData (253) 2 item(s)
Timed: 14/10/14 21:35
3214569mS CMExtnTx: v=4320, p1=8070
CMFacility
Line: type=IPLine 250 Call: lid=321 id=66 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
3214570mS CMExtnTx: v=4320, p1=0
CMSetupAck
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Timed: 14/10/14 21:35
3214570mS CMExtnRx: v=4320, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[7] Type=Default (100) Reason=CMDRdirect Keypad[7]
3214574mS CD: CALL: 321.1060.0 BState=Idle Cut=0 Music=0.0 Aend="Neo Sethibe(4320)" (0.0) Bend="" [] (0.0) CalledNum=7 () CallingNum=4320 (Neo Sethibe) Internal=1 Time=13 AState=Dialling
3214576mS H323Evt: SetOperational 23 10.142.0.10:0 to 0
3214889mS RES: Tue 14/10/2014 21:35:45 FreeMem=51140296 50773648(1) CachedMem=366648 CMMsg=5(7) Buff=5200 1425 999 12374 5 Links=19774 BTree=0 CPU=16/26/180/17821/19187/0
3214889mS RES2: IP 500 8.1(69) Tasks=49 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=151 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=192 TAPI=0 CF=UMNT
3214890mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)
3215280mS PRN: 4320: Digit Pressed 1
3215280mS CMExtnRx: v=4320, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[1] Type=Default (100) Reason=CMDRdirect Keypad[1]
3215850mS PRN: 4320: Digit Pressed 8
3215851mS CMExtnRx: v=4320, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[8] Type=Default (100) Reason=CMDRdirect Keypad[8]
3216570mS PRN: 4320: Digit Pressed 6
3216571mS CMExtnRx: v=4320, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[6] Type=Default (100) Reason=CMDRdirect Keypad[6]
3216571mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: CancelTimer CMTCDelayedProcessing
3216572mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: LOOKUP CALL ROUTE: type=100 called_party=7186 sub= calling=4320 dir=out complete=0 ses=0
3216572mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: ADD TARGET (N): number=7186 type=100 depth=1 nobar=1 setorig=1 ses=0
3217030mS PRN: 4320: Digit Pressed 9
3217030mS CMExtnRx: v=4320, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[9] Type=Default (100) Reason=CMDRdirect Keypad[9]
3217031mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: LOOKUP CALL ROUTE: type=100 called_party=71869 sub= calling=4320 dir=out complete=0 ses=0
3217031mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: ADD TARGET (N): number=71869 type=100 depth=1 nobar=1 setorig=1 ses=0
3217269mS PRN: IP408_FEC(0)::Tick: received 122000 tagged frames (this VLAN ID is 500)
3217390mS PRN: 4320: Digit Pressed 0
3217391mS CMExtnRx: v=4320, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
3217391mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: LOOKUP CALL ROUTE: type=100 called_party=718690 sub= calling=4320 dir=out complete=0 ses=0
3217391mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: ADD TARGET (N): number=718690 type=100 depth=1 nobar=1 setorig=1 ses=0
3217550mS PRN: Monitor Status IP 500 8.1(69)
3217550mS PRN: LAW=A PRI=2, BRI=0, ALOG=8, VCOMP=32, MDM=0, WAN=0, MODU=0 LANM=0 CkSRC=5 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=1(TOT=23)
3217730mS PRN: 4320: Digit Pressed 2
3217731mS CMExtnRx: v=4320, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[2] Type=Default (100) Reason=CMDRdirect Keypad[2]
3217731mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: LOOKUP CALL ROUTE: type=100 called_party=7186902 sub= calling=4320 dir=out complete=0 ses=0
3217731mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: ADD TARGET (N): number=7186902 type=100 depth=1 nobar=1 setorig=1 ses=0
3217971mS PRN: 4320: Digit Pressed 2
3217971mS CMExtnRx: v=4320, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[2] Type=Default (100) Reason=CMDRdirect Keypad[2]
3217972mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: LOOKUP CALL ROUTE: type=100 called_party=71869022 sub= calling=4320 dir=out complete=0 ses=0
3217972mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: ADD TARGET (N): number=71869022 type=100 depth=1 nobar=1 setorig=1 ses=0
3218459mS PRN: 4320: Digit Pressed #
3218460mS CMExtnRx: v=4320, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=321 id=1060 in=0
Called[#] Type=Default (100) Reason=CMDRdirect Keypad[#]
3218460mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: LOOKUP CALL ROUTE: type=100 called_party=71869022# sub= calling=4320 dir=out complete=0 ses=0
3218461mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: ADD TARGET (N): number=71869022# type=100 depth=1 nobar=1 setorig=1 ses=0
3218461mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: USER SC: 71869022# 3 1869022 sc=type=Dial code=7N#, num=.s
3218462mS CMARS: FindActiveARSByGroupID GroupID=4 - Not Found
3218462mS CMLRQ: FindActiveLRQByGroupID GroupID=4 - Not Found
3218463mS CMTARGET: Group Id: 4 has NOT been found in Line: 5
3218463mS CMMap: a=0.1 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder resource busy 1, total 32
3218463mS CMCallEvt: 0.1062.0 -1 BaseEP: NEW CMEndpoint f4abd880 TOTAL NOW=3 CALL_LIST=1
3218468mS CMTARGET: DIAL LINE: 23 GROUP = 4 SUCCESS = f4abd880
3218468mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: CancelTimer CMTCDialToneTimeout
3218468mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: INITIAL TARGETING SUCCEEDED
3218469mS CMTARGET: 321.1060.0 23 Neo Sethibe.0: GetNoAnswerTimer:21
3218469mS CMCallEvt: 0.1061.0 23 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
3218470mS CMCallEvt: 0.1062.0 23 Q931 Trunk:6 CHAN=1: StateChange: END=T CMCSIdle->CMCSOffering
3218471mS CMLineTx: v=6
CMSetup
Line: type=Q931Line 6 Call: lid=0 id=1062 in=0
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ALaw
BChan: slot=0 chan=1
Timed: 14/10/14 21:35
Locale: ens
3218471mS CD: CALL: 321.1060.0 BState=Idle Cut=0 Music=0.0 Aend="Neo Sethibe(4320)" (0.0) Bend="Line 6" [Line 6] (0.0) CalledNum=71869022# () CallingNum=4320 (Neo Sethibe) Internal=0 Time=3910 AState=Dialling
3218475mS ISDNL3Evt: v=6 stacknum=6 State, new=Initiated, old=NullState id=1062



Kindly help resolve this. Would like to hear from people who have setup similar infrastructure as well in terms of whats the best approach, whether to use qsig, etc.

SKVL

 

[amriddle01]

You sent 71869022# to their equipment in that trace

 

[skaval24]

Hi Yes.

I changed that and am getting cause code 102, Cause=102, "Recovery on timer expiry". See trace below;

49492987mS CMExtnEvt: Neo Sethibe: CMExtnHandler::SetCurrent( id: 0->6025 )
49492989mS CMExtnEvt: v=118 State, new=Dialling old=Idle,0,0,Neo Sethibe
49492990mS CMTARGET: 321.6025.0 1530 Neo Sethibe.0: LOOKUP CALL ROUTE: type=100 called_party=74803748 sub= calling=4320 dir=out complete=1 ses=0
49492990mS CMTARGET: 321.6025.0 1530 Neo Sethibe.0: ADD TARGET (N): number=74803748 type=100 depth=1 nobar=1 setorig=1 ses=0
49492991mS CMTARGET: 321.6025.0 1530 Neo Sethibe.0: DEF SC: 74803748 0 sc=type=Dial code=?, num=.
49492992mS CMARS: FindActiveARSByGroupID GroupID=4 - Not Found
49492992mS CMLRQ: FindActiveLRQByGroupID GroupID=4 - Not Found
49492997mS CMTARGET: DIAL LINE: 1530 GROUP = 4 SUCCESS = f4794488
49492997mS CMTARGET: 321.6025.0 1530 Neo Sethibe.0: INITIAL TARGETING SUCCEEDED
49492997mS CMTARGET: 321.6025.0 1530 Neo Sethibe.0: GetNoAnswerTimer:21
49492998mS CMExtnEvt: v=118 State, new=Proceeding old=Dialling,0,0,Neo Sethibe
49493001mS CMLineTx: v=6
CMSetup
Line: type=Q931Line 6 Call: lid=0 id=6027 in=0
Called[74803748] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[] Type=Unknown Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ALaw
BChan: slot=0 chan=1
Timed: 15/10/14 10:27
Locale: ens
49493096mS CMExtnEvt: Refilwe: No user activity
49497937mS CMLineRx: v=6
CMReleaseComp
Line: type=Q931Line 6 Call: lid=0 id=6027 in=0
BChan: slot=0 chan=1
Cause=102, Recovery on timer expiry
49497938mS CMTARGET: 321.6025.0 1530 Neo Sethibe.0: CancelTimer CMTCNoAnswerTimeout
49497945mS CMExtnEvt: Neo Sethibe: CALL LOST (CMCauseRecoveryOnTimerExpiry)
49497945mS CMExtnEvt: Neo Sethibe: Extn(4320) Calling Party Number(4320) Type(CMNTypeInternal)
49497948mS CMExtnEvt: v=118 State, new=CMESCompleted old=Proceeding,0,0,Neo Sethibe
49498655mS CMLineTx: v=17
CMFacility
Line: type=IPLine 17 Call: lid=0 id=6018 in=0
IE CMIEFastStartInfoData (6) 2 item(s)

 

[skaval24]

Here are more traces, relating to ISDNevt.

Have uploaded a file from SSA that shows that the line is disconnected even before the digits are sent across.



10:42:50 50439001mS ISDNL3Evt: v=6 stacknum=6 State, new=ReleaseReq, old=Initiated id=6676
10:42:50 50439006mS ISDNL3Evt: v=6 stacknum=6 State, new=NullState, old=ReleaseReq id=6676
10:42:50 50439007mS CMLineRx: v=6
CMReleaseComp
Line: type=Q931Line 6 Call: lid=0 id=6676 in=0
BChan: slot=0 chan=1
Cause=102, Recovery on timer expiry
10:42:50 50439007mS CMCallEvt: 0.6675.0 1721 TargetingEP: RequestEnd 0.6676.0 1721 Q931 Trunk:6 CHAN=1
10:42:50 50439008mS CMTARGET: 321.6674.0 1721 Neo Sethibe.0: CancelTimer CMTCNoAnswerTimeout
10:42:50 50439008mS CMCallEvt: 0.6675.0 -1 BaseEP: DELETE CMEndpoint f4766758 TOTAL NOW=28 CALL_LIST=13
10:42:50 50439008mS CMCallEvt: 0.6676.0 1721 Q931 Trunk:6 CHAN=1: StateChange: END=B CMCSOffering->CMCSCompleted
10:42:50 50439011mS CMLOGGING: CALL:2014/10/1510:42,00:00:00,000,4320,O,74803748,74803748,NeoSethibe,,,0,,""n/a,0
10:42:50 50439012mS CD: CALL: 321.6674.0 BState=Disconnecting Cut=1 Music=0.0 Aend="Neo Sethibe(4320)" (0.0) Bend="Line 6" [Line 6] (3.34) CalledNum=74803748 () CallingNum=4320 (Neo Sethibe) Internal=0 Time=4935 AState=Dialled
10:42:50 50439012mS CD: CALL: 321.6674.0 Deleted
10:42:50 50439015mS CMExtnEvt: Neo Sethibe: CALL LOST (CMCauseRecoveryOnTimerExpiry)
10:42:50 50439015mS CMExtnEvt: Neo Sethibe: Extn(4320) Calling Party Number(4320) Type(CMNTypeInternal)
10:42:50 50439016mS CMCallEvt: 321.6674.0 -1 Neo Sethibe.0: StateChange: END=X CMCSDialled->CMCSCompletedTone
10:42:50 50439017mS CMExtnTx: v=4320, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=321 id=6674 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIESecurityData (253) 2 item(s)
Timed: 15/10/14 10:42
10:42:50 50439018mS CMExtnTx: v=4320, p1=8070
CMFacility
Line: type=IPLine 250 Call: lid=321 id=118 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
10:42:50 50439018mS CMExtnEvt: v=118 State, new=CMESCompleted old=Proceeding,0,0,Neo Sethibe
10:42:50 50439019mS PRN: CDR - TCPSend maxqueuesize=500 framecount=0 operational=1
10:42:50 50439020mS CMCallEvt: 0.6676.0 -1 Q931 Trunk:6 CHAN=1: StateChange: END=X CMCSCompleted->CMCSDelete
10:42:50 50439020mS CMCallEvt: END CALL:1721 (f48d89d8)
10:42:50 50439021mS CMCallEvt: 0.6676.0 -1 BaseEP: DELETE CMEndpoint f4791b48 TOTAL NOW=27 CALL_LIST=12
10:42:50 50439024mS H323Evt: SetOperational 1687 10.142.0.10:0 to 0
10:42:50 50439025mS CMMap: PCG::AddToneGenerator g E1[7] for cp[283]b0r1 append pcp[286]b0r1 (total 1)
10:42:50 50439025mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[286]b0r1 Configure 0.0
10:42:50 50439025mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[286]b0r1 ConnectIndication 0.0
10:42:50 50439025mS CMMap: a=0.0 b=0.0 pcp[283]b0r1 RTPE1

Thanks,

SKVL

 

[amriddle01]

That shows you are dialling 74803748 and the B end (them) is then disconnecting the call, this is an issue with their kit not emulating the line correctly I'd wager. Have seen the same thing before with call recorder suppliers, we proved it with an ISDN tester in the end and left it with them, took them weeks to figure it out IIRC, but it was their issue

 

[skaval24]

Thanks Amriddle. You are totally right. They came back this afternoon and re-configured it. Apparently the E1 port on their system was supposed to be configured as master. They did it and voila, calls are going through.

 

[amriddle01]

Nice one