Incorrect ISDN error reporting

Asterisk Asterisk Support
1

We have a site with two PRI E1 lines, doing outbound calling. We often get CONGESTION-messages, which should point to the external lines not being available. However, after analysis with the Telco, we found out that all these calls are either busy or invalid numbers.

So it seems that the ISDN error-reporting is having problems, either in the PBX, or at the TelCo. Does anybody have any experience with this, or see a way to get some insight into this ?

Note that we also get valid reports for these situations (ie: we also see calls being reported as BUSY or NOANSWER), but a lot of these are reported as CONGESTION.

Here are the specs:

  • Asterisk 1.2.1
  • Digium TE406P

Here’s an example of an incorrect log-report:

Apr 3 07:10:09 VERBOSE[31686] logger.c: – Executing GotoIf(“IAX2/517-2”, “0?16”) in new stack
Apr 3 07:10:09 DEBUG[31686] pbx.c: Not taking any branch
Apr 3 07:10:09 VERBOSE[31686] logger.c: – Executing Dial(“IAX2/517-2”, “ZAP/g0/09”) in new stack
Apr 3 07:10:09 VERBOSE[31686] logger.c: – Requested transfer capability: 0x00 - SPEECH
Apr 3 07:10:09 VERBOSE[31686] logger.c: – Called g0/09
Apr 3 07:10:10 DEBUG[4083] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/2 span 1
Apr 3 07:10:10 VERBOSE[31686] logger.c: – Zap/2-1 is proceeding passing it to IAX2/517-2
Apr 3 07:10:12 VERBOSE[4083] logger.c: – Channel 0/2, span 1 got hangup request
Apr 3 07:10:12 VERBOSE[31686] logger.c: – Zap/2-1 is circuit-busy
Apr 3 07:10:12 DEBUG[31686] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/2-1
Apr 3 07:10:12 DEBUG[31686] chan_zap.c: Hangup: channel: 2 index = 0, normal = 13, callwait = -1, thirdcall = -1
Apr 3 07:10:12 DEBUG[31686] chan_zap.c: Not yet hungup… Calling hangup once with icause, and clearing call
Apr 3 07:10:12 DEBUG[31686] chan_zap.c: disabled echo cancellation on channel 2
Apr 3 07:10:12 DEBUG[31686] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/2-1
Apr 3 07:10:12 DEBUG[31686] chan_zap.c: Updated conferencing on 2, with 0 conference users
Apr 3 07:10:12 DEBUG[31686] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/2-1
Apr 3 07:10:12 DEBUG[31686] chan_zap.c: disabled echo cancellation on channel 2
Apr 3 07:10:12 VERBOSE[31686] logger.c: – Hungup 'Zap/2-1’
Apr 3 07:10:12 VERBOSE[31686] logger.c: == Everyone is busy/congested at this time (1:0/1/0)
Apr 3 07:10:12 DEBUG[31686] app_dial.c: Exiting with DIALSTATUS=CONGESTION.
Apr 3 07:10:12 VERBOSE[31686] logger.c: – Executing Goto(“IAX2/517-2”, “s-CONGESTION|1”) in new stack
Apr 3 07:10:12 VERBOSE[31686] logger.c: – Goto (macro-dialout-trunk,s-CONGESTION,1)
Apr 3 07:10:12 VERBOSE[31686] logger.c: – Executing NoOp(“IAX2/517-2”, “Dial failed due to CONGESTION”) in new stack
Apr 3 07:10:12 VERBOSE[31686] logger.c: – Executing Macro(“IAX2/517-2”, “outisbusy”) in new stack
Apr 3 07:10:12 VERBOSE[31686] logger.c: – Executing Playback(“IAX2/517-2”, “all-circuits-busy-now”) in new stack

2

At the Asterisk console do “pri debug span 1” and then place the call. Add output here or call Digium support.

3

Here is the output of the CLI on an incorrect report while running “PRI DEBUG SPAN X”; the call was made for ext IAX2/518, using Zap/30, and resulted in a CONGESTION. Note that Zap/31 also started dialing during this log, so some of the data might be coming from that call (I have no experience with these PRI logs, so I kept everything in).

Apr 6 12:08:11 VERBOSE[11563] logger.c: – Executing Dial(“IAX2/518-45”, “ZAP/r0/0134564064”) in new stack
Apr 6 12:08:11 VERBOSE[11563] logger.c: – Making new call for cr 53941
Apr 6 12:08:11 VERBOSE[11563] logger.c: – Requested transfer capability: 0x00 - SPEECH
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Protocol Discriminator: Q.931 (8) len=41
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Call Ref: len= 2 (reference 21173/0x52B5) (Originator)
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Message type: SETUP (5)
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [04
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [04 03
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [04 03 80
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [04 03 80 90
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [04 03 80 90 a3
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [04 03 80 90 a3]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Ext: 1 User information layer 1: A-Law (35)
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [18
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [18 03
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [18 03 a9
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [18 03 a9 83
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [18 03 a9 83 9e
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [18 03 a9 83 9e]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit, PRI Spare: 0, Exclusive Dchan: 0
Apr 6 12:08:11 VERBOSE[11563] logger.c: > ChanSel: Reserved
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Ext: 1 Channel: 30 ]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [28
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [28 03
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [28 03 35
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [28 03 35 31
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [28 03 35 31 38
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [28 03 35 31 38]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Display (len= 3) x¾Q·\Î*[ 518 ]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [6c
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [6c 05
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [6c 05 21
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [6c 05 21 81
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [6c 05 21 81 35
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [6c 05 21 81 35 31
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [6c 05 21 81 35 31 38
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [6c 05 21 81 35 31 38]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Calling Number (len= 7) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Presentation: Presentation permitted, user number passed network screening (1) ‘518’ ]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31 33
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31 33 34
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31 33 34 35
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31 33 34 35 36
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31 33 34 35 36 34
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31 33 34 35 36 34 30
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31 33 34 35 36 34 30 36
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31 33 34 35 36 34 30 36 34
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [70 0b 80 30 31 33 34 35 36 34 30 36 34]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Called Number (len=13) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) ‘0134564064’ ]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [a1
Apr 6 12:08:11 VERBOSE[11563] logger.c: > [a1]
Apr 6 12:08:11 VERBOSE[11563] logger.c: > Sending Complete (len= 1)
Apr 6 12:08:11 VERBOSE[11563] logger.c: – Called r0/0134564064
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Protocol Discriminator: Q.931 (8) len=13
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Call Ref: len= 2 (reference 21173/0x52B5) (Terminator)
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Message type: STATUS (125)
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [08
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [08 03
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [08 03 82
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [08 03 82 e3
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [08 03 82 e3 28
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [08 03 82 e3 28]
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Cause (len= 5) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2)
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Ext: 1 Cause: Unknown (99), class = Protocol Error (6) ]
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Cause data 1: 28 (40, Display IE)
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [14
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [14 01
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [14 01 01
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [14 01 01]
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Call State (len= 3) [ Ext: 0 Coding: CCITT (ITU) standard (0) Call state: Call Initiated (1)
Apr 6 12:08:11 VERBOSE[4083] logger.c: – Processing IE 8 (cs0, Cause)
Apr 6 12:08:11 VERBOSE[4083] logger.c: – Processing IE 20 (cs0, Call State)
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Protocol Discriminator: Q.931 (8) len=10
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Call Ref: len= 2 (reference 21173/0x52B5) (Terminator)
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Message type: CALL PROCEEDING (2)
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [18
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [18 03
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [18 03 a9
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [18 03 a9 83
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [18 03 a9 83 9e
Apr 6 12:08:11 VERBOSE[4083] logger.c: < [18 03 a9 83 9e]
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit, PRI Spare: 0, Exclusive Dchan: 0
Apr 6 12:08:11 VERBOSE[4083] logger.c: < ChanSel: Reserved
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
Apr 6 12:08:11 VERBOSE[4083] logger.c: < Ext: 1 Channel: 30 ]
Apr 6 12:08:11 VERBOSE[4083] logger.c: – Processing IE 24 (cs0, Channel Identification)
Apr 6 12:08:11 DEBUG[4083] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/30 span 1
Apr 6 12:08:11 VERBOSE[11563] logger.c: – Zap/30-1 is proceeding passing it to IAX2/518-45
Apr 6 12:08:12 VERBOSE[11566] logger.c: – AGI Script fixlocalprefix completed, returning 0
Apr 6 12:08:12 VERBOSE[11566] logger.c: – Executing SetVar(“IAX2/512-32”, “OUTNUM=0111415268”) in new stack
Apr 6 12:08:12 VERBOSE[11566] logger.c: – Executing Cut(“IAX2/512-32”, “custom=OUT_1|:|1”) in new stack
Apr 6 12:08:12 WARNING[11566] ast_expr2.y: non-numeric argument
Apr 6 12:08:12 DEBUG[11566] pbx.c: Expression result is '0’
Apr 6 12:08:12 VERBOSE[11566] logger.c: – Executing GotoIf(“IAX2/512-32”, “0?16”) in new stack
Apr 6 12:08:12 DEBUG[11566] pbx.c: Not taking any branch
Apr 6 12:08:12 VERBOSE[11566] logger.c: – Executing Dial(“IAX2/512-32”, “ZAP/r0/0111415268”) in new stack
Apr 6 12:08:12 VERBOSE[11566] logger.c: – Making new call for cr 53942
Apr 6 12:08:12 VERBOSE[11566] logger.c: – Requested transfer capability: 0x00 - SPEECH
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Protocol Discriminator: Q.931 (8) len=41
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Call Ref: len= 2 (reference 21174/0x52B6) (Originator)
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Message type: SETUP (5)
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [04
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [04 03
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [04 03 80
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [04 03 80 90
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [04 03 80 90 a3
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [04 03 80 90 a3]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Ext: 1 User information layer 1: A-Law (35)
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [18
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [18 03
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [18 03 a9
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [18 03 a9 83
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [18 03 a9 83 9f
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [18 03 a9 83 9f]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit, PRI Spare: 0, Exclusive Dchan: 0
Apr 6 12:08:12 VERBOSE[11566] logger.c: > ChanSel: Reserved
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Ext: 1 Channel: 31 ]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [28
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [28 03
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [28 03 35
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [28 03 35 31
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [28 03 35 31 32
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [28 03 35 31 32]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Display (len= 3) x^·\Î*[ 512 ]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [6c
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [6c 05
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [6c 05 21
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [6c 05 21 81
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [6c 05 21 81 35
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [6c 05 21 81 35 31
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [6c 05 21 81 35 31 32
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [6c 05 21 81 35 31 32]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Calling Number (len= 7) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Presentation: Presentation permitted, user number passed network screening (1) ‘512’ ]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31 31
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31 31 31
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31 31 31 34
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31 31 31 34 31
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31 31 31 34 31 35
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31 31 31 34 31 35 32
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31 31 31 34 31 35 32 36
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31 31 31 34 31 35 32 36 38
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [70 0b 80 30 31 31 31 34 31 35 32 36 38]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Called Number (len=13) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) ‘0111415268’ ]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [a1
Apr 6 12:08:12 VERBOSE[11566] logger.c: > [a1]
Apr 6 12:08:12 VERBOSE[11566] logger.c: > Sending Complete (len= 1)
Apr 6 12:08:12 DEBUG[4077] channel.c: Avoiding initial deadlock for 'Zap/31-1’
Apr 6 12:08:12 VERBOSE[11566] logger.c: – Called r0/0111415268
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Protocol Discriminator: Q.931 (8) len=13
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Call Ref: len= 2 (reference 21174/0x52B6) (Terminator)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Message type: STATUS (125)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08 03
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08 03 82
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08 03 82 e3
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08 03 82 e3 28
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08 03 82 e3 28]
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Cause (len= 5) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Ext: 1 Cause: Unknown (99), class = Protocol Error (6) ]
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Cause data 1: 28 (40, Display IE)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [14
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [14 01
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [14 01 01
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [14 01 01]
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Call State (len= 3) [ Ext: 0 Coding: CCITT (ITU) standard (0) Call state: Call Initiated (1)
Apr 6 12:08:12 VERBOSE[4083] logger.c: – Processing IE 8 (cs0, Cause)
Apr 6 12:08:12 VERBOSE[4083] logger.c: – Processing IE 20 (cs0, Call State)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Protocol Discriminator: Q.931 (8) len=10
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Call Ref: len= 2 (reference 21174/0x52B6) (Terminator)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Message type: CALL PROCEEDING (2)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [18
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [18 03
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [18 03 a9
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [18 03 a9 83
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [18 03 a9 83 9f
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [18 03 a9 83 9f]
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit, PRI Spare: 0, Exclusive Dchan: 0
Apr 6 12:08:12 VERBOSE[4083] logger.c: < ChanSel: Reserved
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Ext: 1 Channel: 31 ]
Apr 6 12:08:12 VERBOSE[4083] logger.c: – Processing IE 24 (cs0, Channel Identification)
Apr 6 12:08:12 DEBUG[4083] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/31 span 1
Apr 6 12:08:12 VERBOSE[11566] logger.c: – Zap/31-1 is proceeding passing it to IAX2/512-32
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Protocol Discriminator: Q.931 (8) len=13
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Call Ref: len= 2 (reference 21173/0x52B5) (Terminator)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Message type: DISCONNECT (69)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08 02
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08 02 84
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08 02 84 9b
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [08 02 84 9b]
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the remote user (4)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Ext: 1 Cause: Unknown (27), class = Normal Event (1) ]
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [1e
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [1e 02
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [1e 02 82
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [1e 02 82 88
Apr 6 12:08:12 VERBOSE[4083] logger.c: < [1e 02 82 88]
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2)
Apr 6 12:08:12 VERBOSE[4083] logger.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ]
Apr 6 12:08:12 VERBOSE[4083] logger.c: – Processing IE 8 (cs0, Cause)
Apr 6 12:08:12 VERBOSE[4083] logger.c: – Processing IE 30 (cs0, Progress Indicator)
Apr 6 12:08:12 VERBOSE[4083] logger.c: – Channel 0/30, span 1 got hangup request
Apr 6 12:08:12 VERBOSE[11563] logger.c: – Zap/30-1 is circuit-busy
Apr 6 12:08:12 DEBUG[11563] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/30-1
Apr 6 12:08:12 DEBUG[11563] chan_zap.c: Hangup: channel: 30 index = 0, normal = 40, callwait = -1, thirdcall = -1
Apr 6 12:08:12 DEBUG[11563] chan_zap.c: Not yet hungup… Calling hangup once with icause, and clearing call
Apr 6 12:08:12 VERBOSE[11563] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Disconnect Indication, peerstate Disconnect Request
Apr 6 12:08:12 VERBOSE[11563] logger.c: > Protocol Discriminator: Q.931 (8) len=17
Apr 6 12:08:12 VERBOSE[11563] logger.c: > Call Ref: len= 2 (reference 21173/0x52B5) (Originator)
Apr 6 12:08:12 VERBOSE[11563] logger.c: > Message type: RELEASE (77)
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [08
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [08 02
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [08 02 81
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [08 02 81 9b
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [08 02 81 9b]
Apr 6 12:08:12 VERBOSE[11563] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1)
Apr 6 12:08:12 VERBOSE[11563] logger.c: > Ext: 1 Cause: Unknown (27), class = Normal Event (1) ]
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [7e
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [7e 06
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [7e 06 04
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [7e 06 04 a0
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [7e 06 04 a0 d6
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [7e 06 04 a0 d6 5a
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [7e 06 04 a0 d6 5a 0b
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [7e 06 04 a0 d6 5a 0b 37
Apr 6 12:08:12 VERBOSE[11563] logger.c: > [7e 06 04 a0 d6 5a 0b 37]
Apr 6 12:08:12 VERBOSE[11563] logger.c: > User-User Information (len= 8) [
Apr 6 12:08:12 VERBOSE[11563] logger.c: > User-User Information (len= 8) [ 04
Apr 6 12:08:12 VERBOSE[11563] logger.c: > User-User Information (len= 8) [ 04 20
Apr 6 12:08:12 VERBOSE[11563] logger.c: > User-User Information (len= 8) [ 04 20 56
Apr 6 12:08:12 VERBOSE[11563] logger.c: > User-User Information (len= 8) [ 04 20 56 5a
Apr 6 12:08:12 VERBOSE[11563] logger.c: > User-User Information (len= 8) [ 04 20 56 5a 0b
Apr 6 12:08:12 VERBOSE[11563] logger.c: > User-User Information (len= 8) [ 04 20 56 5a 0b 37
Apr 6 12:08:12 VERBOSE[11563] logger.c: > User-User Information (len= 8) [ 04 20 56 5a 0b 37 ]
Apr 6 12:08:12 DEBUG[11563] chan_zap.c: disabled echo cancellation on channel 30
Apr 6 12:08:12 DEBUG[11563] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/30-1
Apr 6 12:08:12 DEBUG[11563] chan_zap.c: Updated conferencing on 30, with 0 conference users
Apr 6 12:08:12 DEBUG[11563] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/30-1
Apr 6 12:08:12 DEBUG[11563] chan_zap.c: disabled echo cancellation on channel 30
Apr 6 12:08:12 VERBOSE[11563] logger.c: – Hungup 'Zap/30-1’
Apr 6 12:08:12 VERBOSE[11563] logger.c: == Everyone is busy/congested at this time (1:0/1/0)
Apr 6 12:08:12 DEBUG[11563] app_dial.c: Exiting with DIALSTATUS=CONGESTION.
Apr 6 12:08:12 VERBOSE[11563] logger.c: – Executing Goto(“IAX2/518-45”, “s-CONGESTION|1”) in new stack
Apr 6 12:08:12 VERBOSE[11563] logger.c: – Goto (macro-dialout-trunk,s-CONGESTION,1)
Apr 6 12:08:12 VERBOSE[11563] logger.c: – Executing NoOp(“IAX2/518-45”, “Dial failed due to CONGESTION”) in new stack
Apr 6 12:08:12 VERBOSE[11563] logger.c: – Executing Macro(“IAX2/518-45”, “outisbusy”) in new stack
Apr 6 12:08:12 VERBOSE[11563] logger.c: – Executing Playback(“IAX2/518-45”, “all-circuits-busy-now”) in new stack
Apr 6 12:08:12 DEBUG[4077] channel.c: Avoiding initial deadlock for ‘IAX2/518-45’

4

I am facing the same problem.

I am using a TE110P and asterisk 1.2.5. THis happens ony with some numbers not all of them.

Any clue? Thank you very much for your assistance.

Best Regards.

5

In reply to Harry, The telco sends “call proceeding” and then they send a “disconnect”. After the “call proceeding” message the telco should be sending a “connect” message. Without Asterisk receiving that connect message, it won’t do anything as per the q.931 spec. You will need to check with your telco on why they aren’t sending the connect q.931 message.