INTELLIGENT WORK FORUMS
FOR COMPUTER PROFESSIONALS

Log In

Come Join Us!

Are you a
Computer / IT professional?
Join Tek-Tips Forums!
  • Talk With Other Members
  • Be Notified Of Responses
    To Your Posts
  • Keyword Search
  • One-Click Access To Your
    Favorite Forums
  • Automated Signatures
    On Your Posts
  • Best Of All, It's Free!

*Tek-Tips's functionality depends on members receiving e-mail. By joining you are opting in to receive e-mail.

Posting Guidelines

Promoting, selling, recruiting, coursework and thesis posting is forbidden.

Jobs

Waiting for line - CMARS_OUTOFSERVICE

Waiting for line - CMARS_OUTOFSERVICE

(OP)
I have an ancient IP Office 500 Version 4.1(12) that has been quite trouble free for a very long time. I intend to replace it but I need it to hang on for a few more months.

I thought I was having PRI problems with it (we have two - 23 channels each). We got a blue alarm and then a red alarm and I opened a ticket with our telco provider. Everything seems ok on their end of things.

My users are still seeing problems when calling out (no problems inbound). They often (not always) see the message WAITING FOR LINE, hear 5 beeps, then 5 more, then the call generally goes through.

I confirmed that both of the trunks are operational and all the channels are either in-use or idle. I cleared the alarms and they have not returned. We are also nowhere near actually filling up all the channels. There have been absolutely no changes to Shortcodes or ARS either.

I captured the log for an example call and it turned up a few things (numbers and names replaced). In this example John Doe (extension 1045) is calling out to 1-800-123-4567. Can someone smarter than me tell me how to go about troubleshooting this?

RE: Waiting for line - CMARS_OUTOFSERVICE

(OP)
Log:

89249936mS CMARS: Case 1 - dial_delay_time: 4000 has expired - Resolve what we might have - Called Number: 18001234567 Addr: f5a83988
89249936mS CMARS: FORM: Main - Received Number: 18001234567
89249937mS CMARS: FOUND A SHORT CODE - short_code: 1N; - Tel: 1N - Called_Party: 18001234567 - Line Group Id: 0
89249937mS CMARS: CMARSHandler::FindActiveARSByGroupID GroupID=0
89249939mS CMARS: FOUND LINE - Line Id: 1 - using line group id: 0 - Called Number: 18001234567 - Calling Number: 1045
89249939mS CMARS: SEND Setup TO LINE
89249939mS PRN: Setting configured voice gain for ch 23.
89249939mS PRN: PRIU DSP 1: channel 23 (timeslot 46), restore gains tx 10, rx 10
89249940mS CMLineTx: v=1
CMSetup
Line: type=Q931Line 1 Call: lid=0 id=10051 in=0
Called[18001234567] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[s9990001111] Type=Default Plan=Default Pres= (101)
BC: CMTC=3K1Audio CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=0 chan=23
Locale: enu
89249940mS CD: CALL: 0.10048.0 BState=Idle Cut=2 Music=0.0 Aend="John Doe(1045)" (10.29) Bend="" [Line 1] (0.0) CalledNum=18001234567 () CallingNum=1045 (John Doe) Internal=1 Time=8799 AState=Dialling
89249992mS CMLineRx: v=1
CMReleaseComp
Line: type=Q931Line 1 Call: lid=0 id=10051 in=0
89249992mS CMARS: LINE ep Received: CMReleaseComp - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
89249993mS CMLineTx: v=1
CMDisconnect
Line: type=Q931Line 1 Call: lid=0 id=10051 in=0
Cause=16, Normal call clearing
89249993mS CMARS: Target: Short_Code: 1N; - Line_Group_ID: 0 has been set to: CMARS_OUTOFSERVICE
89249994mS CMExtnTx: v=1045, p1=0
CMProgress
Line: type=DigitalExtn 8 Call: lid=0 id=10048 in=0
IE CMIEProgressIndicator (30) cs=CMCSITUT (0), loc=CMLUser (0), pd=CMPDInbandPattern (8)
Display [WAITING FOR LINE]
Timed: 22/09/17 08:38
89249994mS CD: CALL: 0.10048.0 BState=Ringing Cut=3 Music=0.0 Aend="John Doe(1045)" (10.29) Bend="" [] (0.0) CalledNum=18001234567 () CallingNum=1045 (John Doe) Internal=1 Time=8853 AState=Ringing
89249995mS CMLineRx: v=1
CMReleaseComp
Line: type=Q931Line 1 Call: lid=0 id=10051 in=0
Cause=16, Normal call clearing
89250072mS RES: Fri 22/9/2017 08:38:41 FreeMem=80295544(58) CMMsg=4 (4) Buff=200 959 1000 7090 5 Links=14196
89250993mS CMARS: Retarget existing BUSY targets - Num of Busy Targets: 1 - Current Form: Main
89250993mS CMMap: a=21.38 b=0.0 DTMF::AllocateRAS allocated CMRTTonegen resource busy 4, total 8
89250994mS CMMap: a=21.38 b=1.255 T
89250994mS CMMap: PCG::MapBChan pcp[177]b1r0 cp_b f5baa134 other_cp_b f5d19890 type CGTypeDTMF
89250994mS CMMap: a=21.38 b=10.29 M2
89250994mS CMMap: DTMF::PlayTones g T[325] ,EEEEE
89250994mS CMMap: Started playing tones, cp[177]b1r0 (from g null)
89250994mS CMMap: cp[177]b1r0 SetOperGroup from g null to g null not executed, playing tones in progress ,EEEEE
89252815mS CMMap: PCG::UnmapBChan pcp[177]b1r0 cp_b f5baa134 other_cp_b f5d19890
89252815mS CMMap: a=21.38 b=10.29 M0
89252815mS CMMap: a=21.38 b=0.0 T0
89252816mS CMMap: a=21.38 b=0.0 DTMF::~DTMF freed CMRTTonegen resource busy 3, total 8
89256993mS CMARS: Retarget existing BUSY targets - Num of Busy Targets: 1 - Current Form: Main
89256993mS CMARS: Target: Short_Code: 1N; - Line_Group_ID: 0 - Telephone_Number: 1N - Line_Status: CMARS_OUTOFSERVICE
89256995mS CMARS: FOUND LINE - Line Id: 2 - using line group id: 0 - Short Code: 1N; - Called Number: 18001234567 - Calling Number: 1045
89256995mS CMARS: Retarget result=SEND Setup TO LINE
89256996mS PRN: Setting configured voice gain for ch 23.
89256996mS PRN: PRIU DSP 1: channel 55 (timeslot 47), restore gains tx 10, rx 10
89256996mS CMLineTx: v=2
CMSetup
Line: type=Q931Line 2 Call: lid=0 id=10052 in=0
Called[18001234567] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[s9990001111] Type=Default Plan=Default Pres= (101)
BC: CMTC=3K1Audio CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=0 chan=23
Locale: enu
89256996mS CD: CALL: 0.10048.0 BState=Ringing Cut=3 Music=0.0 Aend="John Doe(1045)" (10.29) Bend="" [Line 2] (0.0) CalledNum=18001234567 () CallingNum=1045 (John Doe) Internal=1 Time=15855 AState=Ringing
89256997mS CMMap: a=21.38 b=0.0 DTMF::AllocateRAS allocated CMRTTonegen resource busy 4, total 8
89256997mS CMMap: a=21.38 b=1.255 T
89256997mS CMMap: PCG::MapBChan pcp[177]b1r0 cp_b f5baa134 other_cp_b f5d19890 type CGTypeDTMF
89256998mS CMMap: a=21.38 b=10.29 M2
89256998mS CMMap: DTMF::PlayTones g T[326] ,EEEEE
89256998mS CMMap: Started playing tones, cp[177]b1r0 (from g null)
89256998mS CMMap: cp[177]b1r0 SetOperGroup from g null to g null not executed, playing tones in progress ,EEEEE
89257029mS CMLineRx: v=2
CMProceeding
Line: type=Q931Line 2 Call: lid=0 id=10052 in=0
BChan: slot=0 chan=23
89257029mS CMARS: LINE ep Received: CMProceeding - child->state = CMCSOffering - ARS Call State = CMCSAccept
89257029mS CMTARGET: TargetOnProgress: res: 1
89257029mS CMARS: LINE IS NOW THE B END OF THE CALL - CMARSEndpoint::RequestEnd()
89257030mS CMARS: CMARSEndpoint::CallLost(cause=124) - Address: 0.10050.0 2323 ARS for Main - Call State: CMCSAccept
89257030mS CMExtnTx: v=1045, p1=0
CMProceeding
Line: type=DigitalExtn 8 Call: lid=0 id=10048 in=0
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceISDNTrunk type=2 number=2 channel=23 rx_gain=32 tx_gain=32
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=18001234567
Timed: 22/09/17 08:38
89257031mS CMARS: ~CMARSEndpoint() - Address: f5a83988
89257031mS CD: CALL: 0.10048.0 BState=Ringing Cut=3 Music=0.0 Aend="John Doe(1045)" (10.29) Bend="Line 2" [Line 2] (1.56) CalledNum=18001234567 () CallingNum=1045 (John Doe) Internal=0 Time=15890 AState=Ringing
89257032mS CMMap: Playing in progress, cp[177]b1r0 g null
89257032mS CMMap: cp[177]b1r0 SetOperGroup from g null to g G[327] not executed, playing tones in progress ,EEEEE
89257032mS CMMap: PCG::MapBChan pcp[102]b1r0 cp_b f5cc6934 other_cp_b 0 type CGTypeSimple
89257072mS RES: Fri 22/9/2017 08:38:48 FreeMem=80296172(59) CMMsg=4 (4) Buff=200 958 999 7090 5 Links=14188
89258628mS CMLineRx: v=2
CMProgress
Line: type=Q931Line 2 Call: lid=0 id=10052 in=0
IE CMIEProgressIndicator (30) cs=CMCSITUT (0), loc=CMLPublicNetLocalUser (2), pd=CMPDInbandPattern (8)
89258629mS CMExtnTx: v=1045, p1=0
CMProgress
Line: type=DigitalExtn 8 Call: lid=0 id=10048 in=0
IE CMIEProgressIndicator (30) cs=CMCSITUT (0), loc=CMLPublicNetLocalUser (2), pd=CMPDInbandPattern (8)
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=18001234567
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceISDNTrunk type=2 number=2 channel=23 rx_gain=32 tx_gain=32
Timed: 22/09/17 08:38
89258629mS CD: CALL: 0.10048.0 BState=Ringing Cut=3 Music=0.0 Aend="John Doe(1045)" (10.29) Bend="Line 2" [Line 2] (1.56) CalledNum=18001234567 () CallingNum=1045 (John Doe) Internal=0 Time=17488 AState=Ringing
89258819mS CMMap: PCG::UnmapBChan pcp[177]b1r0 cp_b f5baa134 other_cp_b f5d19890
89258819mS CMMap: a=21.38 b=10.29 M0
89258819mS CMMap: a=21.38 b=0.0 T0
89258819mS CMMap: a=21.38 b=0.0 DTMF::~DTMF freed CMRTTonegen resource busy 3, total 8
89258820mS CMMap: PCG::MapBChan pcp[177]b1r0 cp_b f5baa134 other_cp_b f5cc6934 type CGTypeSimple
89258820mS CMMap: a=1.56 b=10.29 M1
89264748mS CMLineRx: v=2
CMConnect
Line: type=Q931Line 2 Call: lid=0 id=10052 in=0
89264749mS CMExtnTx: v=1045, p1=0
CMConnect
Line: type=DigitalExtn 8 Call: lid=0 id=10048 in=0
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=18001234567
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceISDNTrunk type=2 number=2 channel=23 rx_gain=32 tx_gain=32
Timed: 22/09/17 08:38
89264749mS CMExtnRx: v=1045, p1=0
CMConnectAck
Line: type=DigitalExtn 8 Call: lid=0 id=10048 in=0
89264749mS CMTARGET: 0.10048.0 2323 John Doe.0: ~CMTargetHandler
89264750mS CMLineTx: v=2
CMConnectAck
Line: type=Q931Line 2 Call: lid=0 id=10052 in=0
BChan: slot=0 chan=23
89264750mS CD: CALL: 0.10048.0 BState=Connected Cut=3 Music=0.0 Aend="John Doe(1045)" (10.29) Bend="Line 2" [Line 2] (1.56) CalledNum=18001234567 () CallingNum=1045 (John Doe) Internal=0 Time=23609 AState=Connected
89265072mS RES: Fri 22/9/2017 08:38:56 FreeMem=80301804(58) CMMsg=4 (4) Buff=200 959 1000 7090 5 Links=14192
89268668mS CMLineRx: v=2
CMReleaseComp
Line: type=Q931Line 2 Call: lid=0 id=10052 in=0
BChan: slot=0 chan=23
Cause=16, Normal call clearing
89268669mS ERR: CDRServer discarding - framecount=500
89268670mS CMLOGGING: CALL:2017/09/2208:38,00:00:17,000,1045,O,18001234567,918001234567,JohnDoe,,,0,,""n/a,0
89268671mS CD: CALL: 0.10048.0 BState=Disconnecting Cut=1 Music=0.0 Aend="John Doe(1045)" (10.29) Bend="Line 2" [Line 2] (1.56) CalledNum=18001234567 () CallingNum=1045 (John Doe) Internal=0 Time=27530 AState=Connected
89268671mS CD: CALL: 0.10048.0 Deleted 89268672mS CMExtnTx: v=1045, p1=0
CMReleaseComp
Line: type=DigitalExtn 8 Call: lid=0 id=10048 in=0
Called[918001234567] Type=Default (100) Reason=CMDRdirect Calling[1045] Type=Internal Plan=Default
Cause=16, Normal call clearing
Timed: 22/09/17 08:38
89268674mS CMMap: PCG::UnmapBChan pcp[177]b1r0 cp_b f5baa134 other_cp_b f5cc6934
89268674mS CMMap: a=1.56 b=10.29 M0
89268674mS CMMap: PCG::UnmapBChan pcp[102]b1r0 cp_b f5cc6934 other_cp_b 0
89270672mS CMExtnTx: v=1045, p1=0
CMVoiceMailStatus
Line: type=DigitalExtn 8 Call: lid=0 id=-1 in=0
Called[John Doe Msgs=0 Old=0 Sav=0] Type=Default (100) Reason=CMDRdirect Calling[00000000] Type=Default Plan=Default
Display [John Doe Msgs=0]
Timed: 22/09/17 08:39

RE: Waiting for line - CMARS_OUTOFSERVICE

Try to read the trace yourself here, almost impossible as you can see.
Attach the trace as a file but as it is a ISDN issue enable ISDN filter also

RE: Waiting for line - CMARS_OUTOFSERVICE

I assume you have rebooted the IPO after you got the blue and red alarms.

"Trying is the first step to failure..." - Homer

RE: Waiting for line - CMARS_OUTOFSERVICE

(OP)
Yes, all components on my side of the chain have been rebooted.

things have gotten worse though. I can no longer make outgoing calls. I replaced one of the cables by cutting a new T-1 crossover (after the outbound calls stopped working) to the adtran and it shows the PRI as up and channels available, but users are met with a recording saying "sorry, but your call cannot be connected".

Ugh.

RE: Waiting for line - CMARS_OUTOFSERVICE

(OP)
Call trace:

9/25/17 12:05:29 PM-693ms Line = 2, Seized, Channel ID = 1, Call Ref = 5
9/25/17 12:05:29 PM-695ms Line = 2, Channel = 1, Q.931 Message = Setup, Call Ref = 5, Direction = From Switch, Calling Party Number = xxxxxxxxxxx, Called Party Number = xxxxxxxxxxx
9/25/17 12:05:29 PM-711ms Line = 2, Channel = 1, Q.931 Message = CallProceeding, Call Ref = 5, Direction = To Switch
9/25/17 12:05:29 PM-713ms Call Ref = 5, Originator State = Ringback, Type = User, Destination State = Dialling, Type = Trunk
9/25/17 12:05:29 PM-751ms Line = 2, Channel = 1, Q.931 Message = Progress, Call Ref = 5, Direction = To Switch
9/25/17 12:05:29 PM-752ms Call Ref = 5, Originator State = Ringback, Type = User, Destination State = Outgoing Alerting, Type = Trunk
9/25/17 12:05:29 PM-752ms Call Ref = 5, Alerting, Line = 2, Channel = 1
9/25/17 12:05:35 PM-531ms Line = 2, Channel = 1, Q.931 Message = Disconnect, Call Ref = 5, Direction = To Switch, Cause Code = 18
9/25/17 12:05:35 PM-532ms Line = 2, Channel = 1, Q.931 Message = Release, Call Ref = 5, Direction = From Switch
9/25/17 12:05:35 PM-550ms Line = 2, Channel = 1, Q.931 Message = ReleaseComplete, Call Ref = 5, Direction = To Switch
9/25/17 12:05:35 PM-552ms Call Ref = 5, Originator State = Ringback, Type = User, Destination State = Clearing, Type = Trunk
9/25/17 12:05:35 PM-552ms Call Ref = 5, Disconnect from Destination End
9/25/17 12:05:35 PM-557ms Line = 2, Idle, Channel ID = 1

Thanks very much for your advice. I am no phone pro - doing the best I can in a bad situation.

RE: Waiting for line - CMARS_OUTOFSERVICE

Please read the answers before posting another useless trace.
SSA is nice for a quick look but it is useless for fault finding.

So still no conclusive answer which you maybe would have had with the right trace.

RE: Waiting for line - CMARS_OUTOFSERVICE

(OP)
An ISDN code that came up today:

1888786mS ISDNL3Rx: v=2 peb=2
ISDN Layer3 Pcol=08(Q931) Reflen=2 ref=000B(Local)
Message Type = Disconnect
InformationElement = CAUSE
0000 08 02 82 92

RE: Waiting for line - CMARS_OUTOFSERVICE

(OP)
intrigrant - thank you for taking the time to respond.

If you please, tell me what a useful filter of the trace might be I would be happy to provide it. Layers 1-3 on the ISDN tab for the trunk in question?

RE: Waiting for line - CMARS_OUTOFSERVICE

Looks like you are getting a cause code 18

9/25/17 12:05:35 PM-531ms Line = 2, Channel = 1, Q.931 Message = Disconnect, Call Ref = 5, Direction = To Switch, Cause Code = 18

Cause No. 18 - no user responding.
This cause is used when a called party does not respond to a call establishment message with either an alerting or connect indication within the prescribed period of time allocated.

What it means:
The equipment on the other end does not answer the call. Usually this is a misconfiguration on the equipment being called.

Looks like a providor issue. But I could be wrong. Haven't seen that error before.

Dermis and feline can be divorced by manifold methods.*
*(Disclaimer for all advise given)--'Version Dependent'

RE: Waiting for line - CMARS_OUTOFSERVICE

Everything in the ISDN filter, there is no kill like overkillvader2
Disable all the rest as it is of no importance for this case

RE: Waiting for line - CMARS_OUTOFSERVICE

(OP)
Update:

Talked to my phone service vendor and two bad things are happening:

First - my DIDs were (for years) coded strangely to be prepended with an "s". So number dialing out would appear to the upstream switch as "s8881234567". Some of them are also prepended with "i". No idea why. I inherited this thing. When I switched the s to an i in the call routing suddenly things start working.

Second - my phone provider migrated one of my PRIs to a new switch in their system. This one works. But my second PRI fails every time. I get the feeling from them that it was not migrated or even bonded properly. They were also not even aware of it as a circuit we owned.

The new switch was telling me the number was garbage, which it was. The old switch did not care.

This gummed up things badly also.

Still cleaning up the mess(es) here but posting this for reference in case anyone else encounters something similar.

RE: Waiting for line - CMARS_OUTOFSERVICE

Quote (souldoubt)

recording saying "sorry, but your call cannot be connected".
this means the call is getting dialed & the other end is rejecting it

as to you short codes

S tells the ipo that the following digits are to be placed in the CLI field (the S does not get dialled to line (you will see this when you enable ISDN L3 packets as previously advised)
the 'i' (case sensitive) flags the number as being provided in full international format (all available characters are explained in the manager help files). some equipment may be fussy about the format that the CLI is presented in, you will need to confirm this with your provider.
Most providers will also restrict CLI presentation to only those numbers valid on the circuit, again confirm with your provider.


Do things on the cheap & it will cost you dear

Red Flag This Post

Please let us know here why this post is inappropriate. Reasons such as off-topic, duplicates, flames, illegal, vulgar, or students posting their homework.

Red Flag Submitted

Thank you for helping keep Tek-Tips Forums free from inappropriate posts.
The Tek-Tips staff will check this out and take appropriate action.

Reply To This Thread

Posting in the Tek-Tips forums is a member-only feature.

Click Here to join Tek-Tips and talk with other members!

Resources

Close Box

Join Tek-Tips® Today!

Join your peers on the Internet's largest technical computer professional community.
It's easy to join and it's free.

Here's Why Members Love Tek-Tips Forums:

Register now while it's still free!

Already a member? Close this window and log in.

Join Us             Close