On Mon, Jan 20, 2014 at 5:16 PM, Dale Noll <dn...@wi.rr.com> wrote: > We fairly recently switched service providers for our 4 PRI circuits. > Since that time, we started to notice some failed inbound calls. These > calls terminate with an ISDN cause code 47 'resource unavailble'. Most of > the time I see this error on the first or second channel on the second span > in a trunk group (This is the providers trunk group for hunting, not an > Asterisk trunk group). All the PRIs are setup as individual spans, we are > not using NFAS. If the provider sets the hunt method to 'least recently > used channel', then I can receive calls on other channels on the secondary > span, it is just the first 2 that consistently fail. > > We have had occasion where the error occurs on first span. If enough calls > come in at the same time, callers who happen to land on channel 3 or above > are OK. When the problem happens on the first span, if we physically > disconnect the first span(RED alarm), the calls hunt to the second span and > all calls seem to process properly. The only way to clear the cause 47 > errors from the first span is a power cycle on the provider equipment. > Power cycling my equipment does not solve the problem, only when I cycle > their equipment. > > The provider says the cause 47 is coming from my equipment, yet the 'core > set debug on' log, unless I am reading it wrong, says it is coming from > their side. > > I have a second server as a backup. Both servers have identical hardware > and software. When switching to the backup server, the problem remains. > > I had the same setup on the previous provider, except using NFAS, and did > not have this problem. > > Am I reading the log correctly? >
Yes. Asterisk has accepted the selected channel and CONNECTed the call. It is the peer that is disconnecting the call with cause 47. This really appears to be a problem in the providers equipment. > Do I have something setup incorrectly? > I don't see anything wrong. > Is there any way to get even lower level debugging on the PRI? > Not really. The problem is at layer 3 (Q.931) not layer 2 (Q.921). Turning on intense PRI debug will add nothing but noise to the debug log. <snip> ======================= > Log sample with ISDN debug on > ======================= > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Protocol Discriminator: Q.931 (8) len=87 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < TEI=0 Call Ref: len= 2 (reference 6918/0x1B06) (Sent from originator) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Message Type: SETUP (5) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < [04 03 80 90 a2] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Bearer Capability (len= 5) [ Ext: 1 Coding-Std: 0 Info transfer > capability: Speech (0) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Ext: 1 Trans mode/rate: 64kbps, > circuit-mode (16) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < User information layer 1: u-Law (34) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < [18 03 a9 83 82] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 > Exclusive Dchan: 0 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < ChanSel: As indicated in following octets > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Ext: 1 Coding: 0 Number Specified Channel > Type: 3 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Ext: 1 Channel: 2 Type: CPE] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < [1c 1d 9f 8b 01 00 a1 17 02 01 1f 02 01 00 80 0f 43 65 6c 6c 20 50 68 > 6f 6e 65 20 20 20 57 49] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Facility (len=31, codeset=0) [ 0x9F, 0x8B, 0x01, 0x00, 0xA1, 0x17, > 0x02, 0x01, 0x1F, 0x02, 0x01, 0x00, 0x80, 0x0F, 'Cell Phone WI' ] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < [28 0f 43 65 6c 6c 20 50 68 6f 6e 65 20 20 20 57 49] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Display (len=15) [ Cell Phone WI ] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < [6c 0c 21 80 34 31 34 33 33 31 32 34 37 30] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Calling Number (len=14) [ Ext: 0 TON: National Number (2) NPI: > ISDN/Telephony Numbering Plan (E.164/E.163) (1) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Presentation: Presentation permitted, user > number not screened (0) 'NPANXXXXXX' ] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < [70 08 c1 33 34 34 36 37 31 31] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Called Number (len=10) [ Ext: 1 TON: Subscriber Number (4) NPI: > ISDN/Telephony Numbering Plan (E.164/E.163) (1) '3446711' ] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Making new call for cref 6918 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 Received message for call 0xb750d598 on link 0x9b33f2c TEI/SAPI 0/0 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Processing Q.931 Call Setup > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Processing IE 4 (cs0, Bearer Capability) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Processing IE 24 (cs0, Channel Identification) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Processing IE 28 (cs0, Facility) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Processing IE 40 (cs0, Display) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Processing IE 108 (cs0, Calling Party Number) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Processing IE 112 (cs0, Called Party Number) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Delayed processing IE 28 (cs0, Facility) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 ASN.1 dump > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 Context Specific [11 0x0B] <8B> Len:1 <01> > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 <00> - "~" > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 Context Specific/C [1 0x01] <A1> Len:23 <17> > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 Integer(2 0x02) <02> Len:1 <01> > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 <1F> - "~" > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 Integer(2 0x02) <02> Len:1 <01> > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 <00> - "~" > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 Context Specific [0 0x00] <80> Len:15 <0F> > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 <43 65 6C 6C 20 50 68 6F-6E 65 20 20 20 57 49> - "Cell Phone WI" > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 ASN.1 end > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 interpretation Context Specific [11 0x0B] = 0 0x0000 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 INVOKE Component Context Specific/C [1 0x01] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 invokeId Integer(2 0x02) = 31 0x001F > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 operationValue Integer(2 0x02) = 0 0x0000 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 operationValue = ROSE_QSIG_CallingName > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 callingName Name > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 namePresentationAllowedSimple Context Specific [0 0x00] = > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 <43 65 6C 6C 20 50 68 6F-6E 65 20 20 20 57 49> - "Cell Phone WI" > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 q931.c:8281 post_handle_q931_message: Call 6918 enters state 6 (Call > Present). Hold state: Idle > [Jan 14 12:56:04] VERBOSE[13262] sig_pri.c: [Jan 14 12:56:04] Span 4: > Processing event PRI_EVENT_RING > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 q931.c:5477 q931_call_proceeding: Call 6918 enters state 9 (Incoming Call > Proceeding). Hold state: Idle > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > DL-DATA request > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Protocol Discriminator: Q.931 (8) len=10 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > TEI=0 Call Ref: len= 2 (reference 6918/0x1B06) (Sent to originator) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Message Type: CALL PROCEEDING (2) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 TEI=0 Transmitting N(S)=104, window is open V(A)=104 K=7 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Protocol Discriminator: Q.931 (8) len=10 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > TEI=0 Call Ref: len= 2 (reference 6918/0x1B06) (Sent to originator) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Message Type: CALL PROCEEDING (2) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > [18 03 a9 83 82] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 > Exclusive Dchan: 0 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > ChanSel: As indicated in following octets > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Ext: 1 Coding: 0 Number Specified Channel > Type: 3 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Ext: 1 Channel: 2 Type: CPE] > [Jan 14 12:56:04] VERBOSE[13262] sig_pri.c: [Jan 14 12:56:04] -- > Accepting call from 'NPANXXXXXX' to '3446711' on channel 0/2, span 4 > [Jan 14 12:56:04] VERBOSE[12568] pbx.c: [Jan 14 12:56:04] -- Executing > [3446711@from-pstn:1] NoOp("DAHDI/i4/NPANXXXXXX-bb7", "Seven digits: > 3446711") in new stack > [Jan 14 12:56:04] VERBOSE[12568] pbx.c: [Jan 14 12:56:04] -- Executing > [3446711@from-pstn:2] GotoIf("DAHDI/i4/NPANXXXXXX-bb7", > "0?local-overrides,4143446711,1") in new stack > [Jan 14 12:56:04] VERBOSE[12568] pbx.c: [Jan 14 12:56:04] -- Executing > [3446711@from-pstn:3] Goto("DAHDI/i4/NPANXXXXXX-bb7", "4143446711,1") in > new stack > [Jan 14 12:56:04] VERBOSE[12568] pbx.c: [Jan 14 12:56:04] -- Goto > (from-pstn,4143446711,1) > [Jan 14 12:56:04] VERBOSE[12568] pbx.c: [Jan 14 12:56:04] -- Executing > [4143446711@from-pstn:1] NoOp("DAHDI/i4/NPANXXXXXX-bb7", "IVR call") in > new stack > [Jan 14 12:56:04] VERBOSE[12568] pbx.c: [Jan 14 12:56:04] -- Executing > [4143446711@from-pstn:2] Set("DAHDI/i4/NPANXXXXXX-bb7", > "GROUP()=INBOUND") in new stack > [Jan 14 12:56:04] VERBOSE[12568] pbx.c: [Jan 14 12:56:04] -- Executing > [4143446711@from-pstn:3] Answer("DAHDI/i4/NPANXXXXXX-bb7", "") in new > stack > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 q931.c:5660 q931_connect: Call 6918 enters state 8 (Connect Request). > Hold state: Idle > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > DL-DATA request > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Protocol Discriminator: Q.931 (8) len=14 > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > TEI=0 Call Ref: len= 2 (reference 6918/0x1B06) (Sent to originator) > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Message Type: CONNECT (7) > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 TEI=0 Transmitting N(S)=105, window is open V(A)=105 K=7 > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Protocol Discriminator: Q.931 (8) len=14 > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > TEI=0 Call Ref: len= 2 (reference 6918/0x1B06) (Sent to originator) > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Message Type: CONNECT (7) > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > [18 03 a9 83 82] > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 > Exclusive Dchan: 0 > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > ChanSel: As indicated in following octets > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Ext: 1 Coding: 0 Number Specified Channel > Type: 3 > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Ext: 1 Channel: 2 Type: CPE] > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > [1e 02 81 82] > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) > 0: 0 Location: Private network serving the local user (1) > [Jan 14 12:56:04] VERBOSE[12568] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > Ext: 1 Progress Description: Called > equipment is non-ISDN. (2) ] > [Jan 14 12:56:04] VERBOSE[12568] pbx.c: [Jan 14 12:56:04] -- Executing > [4143446711@from-pstn:4] Wait("DAHDI/i4/NPANXXXXXX-bb7", "") in new stack > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Protocol Discriminator: Q.931 (8) len=9 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < TEI=0 Call Ref: len= 2 (reference 6918/0x1B06) (Sent from originator) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Message Type: RELEASE COMPLETE (90) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < [08 02 80 af] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 > Location: User (0) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 < Ext: 1 Cause: Resource unavailable, unspecified (47), > class = Network Congestion (resource unavailable) (2) ] > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 Received message for call 0xb750d598 on link 0x9b33f2c TEI/SAPI 0/0 > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 -- Processing IE 8 (cs0, Cause) > [Jan 14 12:56:04] VERBOSE[13262] chan_dahdi.c: [Jan 14 12:56:04] PRI Span: > 4 q931.c:8567 post_handle_q931_message: Call 6918 enters state 0 (Null). > Hold state: Idle > [Jan 14 12:56:04] VERBOSE[13262] sig_pri.c: [Jan 14 12:56:04] Span 4: > Processing event PRI_EVENT_HANGUP > [Jan 14 12:56:04] VERBOSE[13262] sig_pri.c: [Jan 14 12:56:04] -- Span > 4: Channel 0/2 got hangup, cause 47 > Richard
-- _____________________________________________________________________ -- Bandwidth and Colocation Provided by http://www.api-digital.com -- New to Asterisk? Join us for a live introductory webinar every Thurs: http://www.asterisk.org/hello asterisk-users mailing list To UNSUBSCRIBE or update options visit: http://lists.digium.com/mailman/listinfo/asterisk-users