Unable to make outbound calls on analog line when incoming call route exists

[gkittelson]

I have a fax machine on an IP Office analog line that has been working fine for months. Firmware version 5.0.26 which hasn't been changed for more than a year. Client stated that they could receive faxes but they couldn't send them. This system shows no licenses installed in it.

When I remove the incoming call route 9864 (for extension 19) to the line it can make outbound calls but, of course, can't receive them. When I reinstate it the line can't make outbound calls but it can receive them.

System is using a T1 card CARRIER/PRIS T1 with seven channels in service and the rest are out of service.

SSA shows calls as incompatible when dialing. Also interesting is that the Status shows Attempt to use a feature for which no licenses are installed License type: IP500 Universal PRI (additional channels). This is strange because it should need a any licenses for over the first eight channels from what I understand.

I have tried rebooting the IP Office, I have deleted the user and re-created it. I have deleted the incoming call route and re-created it. I have tried the second analog port, which wasn't being used and it exhibits the same behavior.

I didn't sell this system to the client and I have no record of there were ever any more licenses in it, but I don't believe at this version level it should need them.

Here is the trace:
6593818mS CMCallEvt: 0.1390.0 -1 BaseEP: NEW CMEndpoint f54fe01c TOTAL NOW=1 CALL_LIST=0
6593818mS CMCallEvt: 0.1390.0 -1 FAX 9864.-1: NEW CMExtnEndpoint f54fe01c, Name=FAX 9864, Extn=19, Phys Extn=19
6593818mS CMCallEvt: CREATE CALL:97 (f550c8b4)
6593818mS CMCallEvt: 0.1391.0 -1 BaseEP: NEW CMEndpoint f551cc94 TOTAL NOW=2 CALL_LIST=0
6593820mS CMExtnEvt: FAX 9864: CMExtnHandler::SetCurrent( id: 0->1390 )
6593820mS CMExtnRx: v=19, p1=0
CMSetup
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[19] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
6593820mS CMCallEvt: 0.1390.0 97 FAX 9864.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
6593821mS CMExtnEvt: v=2 State, new=Connected old=Idle,0,0,FAX 9864
6593821mS CMTARGET: 0.1390.0 97 FAX 9864.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=19 dir=out complete=0 ses=0
6593821mS CMTARGET: 0.1390.0 97 FAX 9864.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
6593822mS CMCallEvt: 0.1390.0 97 FAX 9864.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
6593822mS CMExtnEvt: v=2 State, new=Dialling old=Connected,0,0,FAX 9864
6593822mS CMExtnTx: v=19, p1=0
CMSetupAck
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
BChan: slot=4 chan=18
UUI type=Local [......2Pd.] [0x00 0x02 0x00 0x00 0x01 0x02 0x32 0x50 0x64 0x00 ]
Timed: 31/01/13 13:17
6593823mS CD: CALL: 0.1390.0 BState=Idle Cut=1 Music=3.0 Aend="FAX 9864(19)" (4.18) Bend="" [] (0.0) CalledNum= () CallingNum=19 (FAX 9864) Internal=1 Time=5 AState=DialInitiated
6593824mS CMMap: a=4.18 b=0.0 D1
6594236mS RES: Thu 31/1/2013 13:17:10 FreeMem=72044924(1) CMMsg=8 (10) Buff=200 961 999 7414 5 Links=1502
6594236mS RES2: IP 500 5.0(26) Tasks=34 RTEngine=0 CMRTEngine=0 Timer=47 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
6594312mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[9] Type=Default (100) Reason=CMDRdirect
6594313mS CMTARGET: 0.1390.0 97 FAX 9864.0: Setting Hard Timer 4000
6594313mS CMTARGET: 0.1390.0 97 FAX 9864.0: LOOKUP CALL ROUTE: type=100 called_party=9 sub= calling=19 dir=out complete=0 ses=0
6594313mS CMTARGET: 0.1390.0 97 FAX 9864.0: ADD TARGET (N): number=9 type=100 depth=1 nobar=1 setorig=1 ses=0
6594313mS CMTARGET: 0.1390.0 97 FAX 9864.0: SYS SC: 9 2 sc=type=Dial code=9N, num=N callinfop->sending_complete=0 secondary_dialtone=
6594314mS CMARS: FindActiveARSByGroupID GroupID=50 - Found
6594314mS CMARS: MakeCallTarget - Called Number:
6594314mS CMCallEvt: 0.1392.0 -1 BaseEP: NEW CMEndpoint f54c6f38 TOTAL NOW=3 CALL_LIST=1
6594314mS CMTARGET: 0.1390.0 97 FAX 9864.0: CancelTimer CMTCDelayedProcessing
6594314mS CMTARGET: 0.1390.0 97 FAX 9864.0: INITIAL TARGETING SUCCEEDED
6594315mS CMTARGET: 0.1390.0 97 FAX 9864.0: GetNoAnswerTimer:15
6594315mS CMCallEvt: 0.1391.0 97 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
6594316mS CMCallEvt: 0.1392.0 97 ARS for Main: StateChange: END=T CMCSIdle->CMCSOffering
6594317mS CMCallEvt: 0.1391.0 97 TargetingEP: RequestEnd 0.1392.0 97 ARS for Main
6594317mS CMTARGET: 0.1390.0 97 FAX 9864.0: CancelTimer CMTCNoAnswerTimeout
6594317mS CMCallEvt: 0.1392.0 97 ARS for Main: StateChange: END=B CMCSOffering->CMCSOverlapRecv
6594318mS CMExtnTx: v=19, p1=0
CMProgress
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
BChan: slot=4 chan=18
IE CMIEProgressIndicator (30) cs=CMCSITUT (0), loc=CMLUser (0), pd=CMPDInbandPattern (8)
Display [TRANSFERABLE_SEC_DIAL_TONE]
Timed: 31/01/13 13:17
6594318mS CMARS: FORM: Main - Received Number:
6594318mS CMARS: CMARSTargetingPending
6594318mS CMCallEvt: 0.1391.0 -1 TargetingEP: StateChange: END=X CMCSOffering->CMCSDelete
6594318mS CMCallEvt: 0.1391.0 -1 BaseEP: DELETE CMEndpoint f551cc94 TOTAL NOW=2 CALL_LIST=1
6594319mS CD: CALL: 0.1390.0 BState=Idle Cut=2 Music=3.0 Aend="FAX 9864(19)" (4.18) Bend="" [] (0.0) CalledNum=9 () CallingNum=19 (FAX 9864) Internal=1 Time=501 AState=Dialling
6594320mS CMMap: a=4.18 b=0.0 D1
6594581mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[3] Type=Default (100) Reason=CMDRdirect
6594582mS CMARS: FORM: Main - Received Number: 3
6594582mS CMARS: CMARSTargetingPending
6594583mS CMMap: a=4.18 b=0.0 D0
6594757mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[0] Type=Default (100) Reason=CMDRdirect
6594758mS CMARS: FORM: Main - Received Number: 30
6594758mS CMARS: CMARSTargetingPending
6594905mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[3] Type=Default (100) Reason=CMDRdirect
6594906mS CMARS: FORM: Main - Received Number: 303
6594906mS CMARS: CMARSTargetingPending
6595135mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[6] Type=Default (100) Reason=CMDRdirect
6595136mS CMARS: FORM: Main - Received Number: 3036
6595136mS CMARS: CMARSTargetingPending
6595323mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[3] Type=Default (100) Reason=CMDRdirect
6595324mS CMARS: FORM: Main - Received Number: 30363
6595324mS CMARS: CMARSTargetingPending
6595593mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[7] Type=Default (100) Reason=CMDRdirect
6595594mS CMARS: FORM: Main - Received Number: 303637
6595594mS CMARS: CMARSTargetingPending
6595851mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[9] Type=Default (100) Reason=CMDRdirect
6595852mS CMARS: FORM: Main - Received Number: 3036379
6595852mS CMARS: CMARSTargetingPending
6596013mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[9] Type=Default (100) Reason=CMDRdirect
6596014mS CMARS: FORM: Main - Received Number: 30363799
6596014mS CMARS: CMARSTargetingPending
6596241mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[7] Type=Default (100) Reason=CMDRdirect
6596242mS CMARS: FORM: Main - Received Number: 303637997
6596242mS CMARS: CMARSTargetingPending
6596457mS CMExtnRx: v=19, p1=0
CMInformation
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
Called[9] Type=Default (100) Reason=CMDRdirect
6596458mS CMARS: FORM: Main - Received Number: 3036379979
6596458mS CMARS: FOUND A SHORT CODE - short_code: xxxxxxxxxxN - Tel: N - Called_Party: 3036379979 - Line Group Id: 0
6596458mS CMARS: FindActiveARSByGroupID GroupID=0 - Not Found
6596458mS CMLRQ: FindActiveLRQByGroupID GroupID=0 - Not Found
6596459mS CMCallEvt: 0.1393.0 -1 BaseEP: NEW CMEndpoint f55135e0 TOTAL NOW=3 CALL_LIST=1
6596460mS CMARS: FOUND LINE - Line Id: 13 - using line group id: 0 - Called Number: 3036379979 - Calling Number: 19
6596461mS CMARS: SEND Setup TO LINE
6596461mS CMCallEvt: 0.1393.0 97 Q931 Trunk:13 CHAN=7: StateChange: END=child CMCSIdle->CMCSOffering
6596461mS PRN: Setting configured voice gain for ch 7.
6596461mS CMLineTx: v=13
CMSetup
Line: type=Q931Line 13 Call: lid=0 id=1393 in=0
Called[3036379979] Type=National (2) Reason=CMDRdirect Calling[9864] Type=National Plan=ISDN Pres=AllowedIndSend (101)
BC: CMTC=3K1Audio CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=0 chan=7
Locale: enu
6596462mS CD: CALL: 0.1390.0 BState=Idle Cut=2 Music=0.0 Aend="FAX 9864(19)" (4.18) Bend="" [Line 13] (0.0) CalledNum=93036379979 () CallingNum=19 (FAX 9864) Internal=1 Time=2644 AState=Dialling
6596463mS ISDNL3Evt: v=13 stacknum=13 State, new=Initiated, old=NullState id=1393
6596499mS ISDNL3Evt: v=13 stacknum=13 State, new=Proceeding, old=Initiated id=1393
6596500mS CMLineRx: v=13
CMProceeding
Line: type=Q931Line 13 Call: lid=0 id=1393 in=0
BChan: slot=0 chan=7
6596500mS CMARS: LINE ep Received: CMProceeding - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
6596500mS CMARS: LINE IS NOW THE B END OF THE CALL - CMARSEndpoint::RequestEnd()
6596500mS CMARS: CMARSEndpoint::CallLost(cause=124) - Address: 0.1392.0 97 ARS for Main - Call State: CMCSOverlapRecv
6596501mS CMCallEvt: 0.1392.0 -1 ARS for Main: StateChange: END=X CMCSOverlapRecv->CMCSDelete
6596501mS CMCallEvt: 0.1393.0 97 Q931 Trunk:13 CHAN=7: StateChange: END=B CMCSOffering->CMCSAccept
6596502mS CMCallEvt: 0.1390.0 97 FAX 9864.0: StateChange: END=A CMCSDialling->CMCSDialled
6596502mS CMExtnEvt: v=2 State, new=Proceeding old=Dialling,0,0,FAX 9864
6596502mS CMExtnTx: v=19, p1=0
CMProceeding
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
BChan: slot=4 chan=18
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=93036379979
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=5 class=CMDeviceISDNTrunk type=2 number=13 channel=7 rx_gain=32 tx_gain=32 ep_callid=1393 ipaddr=10.0.0.9 apps=0
Timed: 31/01/13 13:17
6596502mS CMCallEvt: 0.1392.0 -1 BaseEP: DELETE CMEndpoint f54c6f38 TOTAL NOW=2 CALL_LIST=1
6596503mS CD: CALL: 0.1390.0 BState=Ringing Cut=3 Music=0.0 Aend="FAX 9864(19)" (4.18) Bend="Line 13" [Line 13] (6.8) CalledNum=3036379979 () CallingNum=19 (FAX 9864) Internal=0 Time=2685 AState=Dialled
6596504mS CMMap: PCG::MapBChan pcp[122]b1r0 cp_b f59b61b0 other_cp_b 0 type CGTypeSimple
6596504mS CMMap: PCG::MapBChan pcp[104]b1r0 cp_b f59bf95c other_cp_b f59b61b0 type CGTypeSimple
6596504mS CMMap: a=4.18 b=6.8 M1
6596577mS ISDNL3Evt: v=13 stacknum=13 State, new=ReleaseReq, old=Proceeding id=1393
6596586mS ISDNL3Evt: v=13 stacknum=13 State, new=NullState, old=ReleaseReq id=1393
6596587mS CMLineRx: v=13
CMReleaseComp
Line: type=Q931Line 13 Call: lid=0 id=1393 in=0
BChan: slot=0 chan=7
Cause=1, Unallocated (unassigned) number
6596587mS CMCallEvt: 0.1393.0 97 Q931 Trunk:13 CHAN=7: StateChange: END=B CMCSAccept->CMCSCompleted
6596589mS CMLOGGING: CALL:2013/01/3113:17,00:00:00,000,19,O,3036379979,93036379979,FAX9864,,,0,,""n/a,0
6596589mS CD: CALL: 0.1390.0 BState=Disconnecting Cut=1 Music=0.0 Aend="FAX 9864(19)" (4.18) Bend="Line 13" [Line 13] (6.8) CalledNum=3036379979 () CallingNum=19 (FAX 9864) Internal=0 Time=2771 AState=Dialled
6596589mS CD: CALL: 0.1390.0 Deleted
6596590mS CMExtnEvt: FAX 9864: CALL LOST (CMCauseUnallocatedNumber)
6596590mS CMExtnEvt: FAX 9864: Extn(19) Calling Party Number(19) Type(CMNTypeInternal)
6596591mS CMCallEvt: 0.1390.0 -1 FAX 9864.0: StateChange: END=X CMCSDialled->CMCSCompletedTone
6596591mS CMExtnEvt: v=2 State, new=CMESCompleted old=Proceeding,0,0,FAX 9864
6596591mS CMCallEvt: 0.1393.0 -1 Q931 Trunk:13 CHAN=7: StateChange: END=X CMCSCompleted->CMCSDelete
6596591mS CMCallEvt: END CALL:97 (f550c8b4)
6596592mS CMCallEvt: 0.1393.0 -1 BaseEP: DELETE CMEndpoint f55135e0 TOTAL NOW=1 CALL_LIST=0
6596593mS CMMap: PCG::UnmapBChan pcp[122]b1r0 cp_b f59b61b0 other_cp_b f59bf95c
6596593mS CMMap: a=6.8 b=4.18 M0
6596594mS CMMap: PCG::UnmapBChan pcp[104]b1r0 cp_b f59bf95c other_cp_b 0
6596594mS CMMap: a=21.7 b=0.0 DTMF::AllocateRAS allocated CMRTTonegen resource busy 5, total 8
6596594mS CMMap: a=21.7 b=1.255 T
6596594mS CMMap: a=21.7 b=4.18 M2
6599076mS H323Evt: Recv: RegistrationRequest 10.0.0.228; Endpoints registered: 6; Endpoints in registration: 0
6599179mS CMExtnRx: v=19, p1=0
CMReleaseComp
Line: type=AnalogueExtn 4 Call: lid=0 id=2 in=0
6599180mS CMCallEvt: 0.1390.0 -1 FAX 9864.0: StateChange: END=X CMCSCompletedTone->CMCSCompleted
6599180mS CMExtnEvt: v=2 State, new=PortRecoverDelay old=CMESCompleted,0,0,FAX 9864
6599180mS CMExtnEvt: FAX 9864: CALL LOST (CMCauseForceClear)
6599180mS CMExtnEvt: FAX 9864: Extn(19) Calling Party Number(19) Type(CMNTypeInternal)
6599180mS CMExtnEvt: FAX 9864: CMExtnHandler::SetCurrent( id: 1390->0 )
6599181mS CMCallEvt: 0.1390.0 -1 FAX 9864.-1: StateChange: END=X CMCSCompleted->CMCSDelete

 

[gkittelson]

I'm sorry for the extra half of the trace...I didn't mean to copy the first part...

 

[amriddle01]

The carrier doesn't like you sending the DDI/DID out and rejects the call, removing the incoming call route means it doesn't send the DDI/DID out (it does this by default) so that's why it works


Avaya Implementation Qualified Professional Specialist Technical Engineer (AIQPSTE)

 

[gkittelson]

WOW! I would never have thought of that. I'll add the short code to send the outgoing number with it and see if that fixes it and let you know!

 

[gkittelson]

Perfect! Adding the short code to send the full 10 digit number allowed the outgoing call to work. Thank you Cbeyond for not telling me you made this change and wasting a few hours of my day...lol...

Thank you again amiriddle!

Guy Kittelson
Avaya ACSS

 

[amriddle01]

No worries


Avaya Implementation Qualified Professional Specialist Technical Engineer (AIQPSTE)

 

[tlpeter]

Guy Kittelson
Avaya ACSS

No offense but being an ACSS means you should be able to read monitor traces and then act on it.
You should have ssen this line:

Cause=1, Unallocated (unassigned) number


BAZINGA!

I'm not insane, my mother had me tested!

 

[1043]

ACSS just means your good at taking tests.