ISDN not playing back Busy tones when extension busy

General Help
1

Hi All

I’ve just been made aware of a strange issue regarding people dialling in from the outside to a number that is busy. When they do all they hear is ringing for 20seconds then they get disconnected

Looking back the logs it’s been going on since I put the system in.

The calls are coming in via an ISDNe circuit from BT. The extension they are trying to ring has no voicemail, forward or call waiting set. Ringing it internally when busy plays back the busy tones but the same is not happening when calling in from the outside

Can anyone advise?
Thanks

Asterisk 11
FreePBX 2.11

2

Hi
For UK PRI try setting

overlapdial=yes
pridialplan=unknown
prilocaldialplan=unknown
priindication=outofband

we have pri on many site with no issues
Ian

3

priindication=outofband has stopped the long 20 second ringing

However, it’s not as I thought it would be. When ringing in from the outside now callers get a fraction of a second ringing then a long disconnect tone from BT. Looking at the logs it looks like the ISDN is working faster than the system can check if the line is busy or not. When it gets a busy response it hangs up but by this point the ISDN seems to have been answered

Is this normal operation? - I would have expected the busy tones instantly.

My debug is too long to post and it won’t let me upload a txt file, however I have a trace of a call including the ISDN debug. An external call to an extension that is busy. The external caller gets a fraction of a second ringing then a long tone (disconnect tone from BT) rather than the busy tone.

This is an extract from the end of the call:

[2015-10-25 12:50:09] VERBOSE[4848][C-00000d12] chan_sip.c: – Got SIP response 486 “Busy here” back from 10.10.0.18:5060
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] app_dial.c: – SIP/5024-000000b5 is busy
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] app_dial.c: == Everyone is busy/congested at this time (1:1/0/0)
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-dial-one:44] ExecIf(“DAHDI/i1/07xxxxxxxxx-83”, “0?MacroExit()”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-dial-one:45] ExecIf(“DAHDI/i1/07xxxxxxxxx-83”, “0?Set(DIALSTATUS=)”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-dial-one:46] GosubIf(“DAHDI/i1/07xxxxxxxxx-83”, “0?s-BUSY,1()”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-dial-one:47] MacroExit(“DAHDI/i1/07xxxxxxxxx-83”, “”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-exten-vm:10] Set(“DAHDI/i1/07xxxxxxxxx-83”, “SV_DIALSTATUS=BUSY”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-exten-vm:11] GosubIf(“DAHDI/i1/07xxxxxxxxx-83”, “0?docfu,1()”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-exten-vm:12] GosubIf(“DAHDI/i1/07xxxxxxxxx-83”, “0?docfb,1()”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-exten-vm:13] Set(“DAHDI/i1/07xxxxxxxxx-83”, “DIALSTATUS=BUSY”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-exten-vm:14] ExecIf(“DAHDI/i1/07xxxxxxxxx-83”, “0?MacroExit()”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-exten-vm:15] GotoIf(“DAHDI/i1/07xxxxxxxxx-83”, “1?s-BUSY,1”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Goto (macro-exten-vm,s-BUSY,1)
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s-BUSY@macro-exten-vm:1] GotoIf(“DAHDI/i1/07xxxxxxxxx-83”, “0?exit,1”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s-BUSY@macro-exten-vm:2] PlayTones(“DAHDI/i1/07xxxxxxxxx-83”, “busy”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s-BUSY@macro-exten-vm:3] Busy(“DAHDI/i1/07xxxxxxxxx-83”, “20”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] app_macro.c: == Spawn extension (macro-exten-vm, s-BUSY, 3) exited non-zero on ‘DAHDI/i1/07xxxxxxxxx-83’ in macro ‘exten-vm’
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: == Spawn extension (from-did-direct, 5024, 2) exited non-zero on ‘DAHDI/i1/07xxxxxxxxx-83’
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [h@from-did-direct:1] Macro(“DAHDI/i1/07xxxxxxxxx-83”, “hangupcall,”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“DAHDI/i1/07xxxxxxxxx-83”, “1?theend”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Goto (macro-hangupcall,s,3)
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-hangupcall:3] ExecIf(“DAHDI/i1/07xxxxxxxxx-83”, “0?Set(CDR(recordingfile)=)”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: – Executing [s@macro-hangupcall:4] Hangup(“DAHDI/i1/07xxxxxxxxx-83”, “”) in new stack
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘DAHDI/i1/07xxxxxxxxx-83’ in macro ‘hangupcall’
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on ‘DAHDI/i1/07xxxxxxxxx-83’
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 q931.c:6837 q931_hangup: Hangup other cref:118
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 q931.c:6594 __q931_hangup: ourstate Call Received, peerstate Call Delivered, hold-state Idle
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 q931.c:5783 q931_disconnect: Call 118 enters state 11 (Disconnect Request). Hold state: Idle
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > DL-DATA request
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8) len=9
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 118/0x76) (Sent to originator)
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > Message Type: DISCONNECT (69)
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 TEI=0 Transmitting N(S)=8, window is open V(A)=8 K=7
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8) len=9
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 118/0x76) (Sent to originator)
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > Message Type: DISCONNECT (69)
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > [08 02 81 91]
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
[2015-10-25 12:50:09] VERBOSE[19249] chan_dahdi.c: PRI Span: 1 > Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
[2015-10-25 12:50:09] VERBOSE[19249][C-00000d12] chan_dahdi.c: – Hungup ‘DAHDI/i1/07xxxxxxxxx-83’
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 < Protocol Discriminator: Q.931 (8) len=5
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 118/0x76) (Sent from originator)
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 < Message Type: RELEASE (77)
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 Received message for call 0x7f43f4005660 on link 0x164cb10 TEI/SAPI 0/0
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 q931.c:8620 post_handle_q931_message: Call 118 enters state 0 (Null). Hold state: Idle
[2015-10-25 12:50:09] VERBOSE[4831] sig_pri.c: Span 1: Processing event PRI_EVENT_HANGUP(6)
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 q931.c:6837 q931_hangup: Hangup other cref:118
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 q931.c:6594 __q931_hangup: ourstate Null, peerstate Release Request, hold-state Idle
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > DL-DATA request
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8) len=9
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 118/0x76) (Sent to originator)
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > Message Type: RELEASE COMPLETE (90)
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 TEI=0 Transmitting N(S)=9, window is open V(A)=9 K=7
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8) len=9
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 118/0x76) (Sent to originator)
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > Message Type: RELEASE COMPLETE (90)
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > [08 02 81 90]
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ]
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 q931.c:6837 q931_hangup: Hangup other cref:118
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 q931.c:6594 __q931_hangup: ourstate Null, peerstate Null, hold-state Idle
[2015-10-25 12:50:09] VERBOSE[4831] chan_dahdi.c: PRI Span: 1 Destroying call 0x7f43f4005660, ourstate Null, peerstate Null, hold-state Idle

4

Does anyone have any update on this?