FRAME_CONTROL (5) -- Dropped calls on PRI

rafael_uswo · February 28, 2006, 10:48pm

Shortly after our upgrade to 1.2.1, we began experiencing random hangups on inbound and outbound calls. This problem continued after a second upgrade to 1.2.3. After enabling debugging and having users report disconnected calls – I was able to correlate the following debug entry with the hangups:

channel.c: Got a FRAME_CONTROL (5) frame on channel Zap/25-1

From what I can tell (I’m not a strong C programmer or a telco guy) – I’m getting an AST_CONTROL_BUSY in the middle of a bridged call, which causes the channel to unbridge and cleanup.

I’ve worked around the disconnect for now by returrning AST_BRIDGE_RETRY when this situation is encountered. It appears to be working, as no calls have dropped since, although I’m still looking for answers to the following:

Why would I be getting a BUSY frame in the middle of a bridged call?
What side-effects could this work around have on the system?

Any input\feedback would be appreciated.

Below is the code, including my work around, starting at line 3268 of channel.c:

[code] if ((f->frametype == AST_FRAME_CONTROL) && !(config->flags & AST_BRIDGE_IGNORE_SIGS)) {
if ((f->subclass == AST_CONTROL_HOLD) || (f->subclass == AST_CONTROL_UNHOLD) ||
(f->subclass == AST_CONTROL_VIDUPDATE)) {
ast_indicate(who == c0 ? c1 : c0, f->subclass);
} else {
if (f->subclass == AST_CONTROL_BUSY) {
ast_frame_dump(who->name, f, “<<”);
ast_log(LOG_NOTICE, “I SHOULD HAVE HUNG UP %s JUST NOW!!!\n”, who->name);
ast_log(LOG_DEBUG, “Got a FRAME_CONTROL (%d) frame on channel %s\n”, f->subclass, who->name);
res = AST_BRIDGE_RETRY;
} else {

                                    *fo = f;
                                    *rc = who;
                                    res =  AST_BRIDGE_COMPLETE;
                                    ast_log(LOG_DEBUG, "Got a FRAME_CONTROL (%d) frame on channel %s\n", f->subclass, who->name);
                            }
                                    break;
                    }
            }[/code]

-Rafael

rusty · March 1, 2006, 7:11am

It may just be the 1.2.3 here is the first line of the changelog of 2.4

Asterisk 1.2.4 Released

2006-01-30 17:08 +0000 [r8905] Kevin P. Fleming kpfleming@digium.com

* channels/chan_zap.c: disable buggy PRI user-user code until it can be fixed

rafael_uswo · March 2, 2006, 2:15pm

Indeed, the only difference in chan_zap.c between 1.2.3 and 1.2.4 is that the user-user code is disabled. I’ve compiled the 1.2.4 version of chan_zap.c into my current installation to see if that is what is causing my AST_CONTROL_BUSY frames.

Thank you.

-Rafael

rafael_uswo · March 8, 2006, 6:43pm

The changes to chan_zap.c do not affect the errors. I am still getting log entries indicating the problem is occuring; however, the channels are no longer unbridged when this occurs.

From my CLI:
< [ TYPE: Control (4) SUBCLASS: Busy (5) ] [Zap/25-1]

Mar 8 13:38:11 NOTICE[1771]: channel.c:3278 ast_generic_bridge: I SHOULD HAVE HUNG UP Zap/25-1 JUST NOW!!!

Mr_Zdeeck · March 21, 2006, 11:14am

I’d like to thank you for this whole thread, it’s like light at the end of the tunnel for me, I was messing with this problem for a week! (after upgrade 1.0.9 -> 1.2.5)

I’ve bugreported this to bugs.digium.com and it seems that it’s being fixed in the main tree!

rafael_uswo · March 21, 2006, 3:08pm

Mr. Z, Were you able to resolve your problems using the same code?

paulh · May 16, 2006, 7:13am

I have a client with much the same problem - has the latest version of Zaptel been updated to work aroung this issue?

micuzzo · December 6, 2006, 3:43pm

hi,
i’m having exactly same problem: 4-10 calls are dropped every day (on about a total of 2-300).
I have asterisk-1.2.9.1 and zaptel-1.2.6.

Please update me on this issue.

Bye
Domenico Viggiani

baconbuttie · December 6, 2006, 4:14pm

the first thing anyone is going to suggest is going to be an upgrade to Zaptel 1.2.11. it’s possible your issue has been fixed, so i would look at the changelog for zaptel and then maybe install and test the latest version.

kumatel · December 19, 2006, 9:03am

Has Zaptel 1.2.11 source resolved the Problem? I am using Zaptel 1.2.8 and facing the same problems, from 100 calls 10 of them dropping during the call with Got a FRAME_CONTROL (5)

Many thanks
Mathias

micuzzo · December 19, 2006, 9:17am

I’m planning to update my Asterisk servers between Christmas and New Year!

mdruedal · December 20, 2006, 6:52am

Hi, I’m having the same issues, My client is having dropped calls as well,
I’m running Asterisk Asterisk 1.2.14 with zaptel-1.2.12 and libpri-1.2.4 with an Te210p on an Dell 850 with 1Gb ram.
Any help would be very much appreciated. Thanks!

Here is what comes out of the log with pri intense debug span 1 turned on:

Dec 19 14:04:49 VERBOSE[4502] logger.c: T203 counter expired, sending RR and scheduling T203 again
Dec 19 14:04:49 VERBOSE[4502] logger.c: Sending Receiver Ready (51)
Dec 19 14:04:49 VERBOSE[4502] logger.c:

[ 00 01 01 67 ]
Dec 19 14:04:49 VERBOSE[4502] logger.c:
Supervisory frame:
Dec 19 14:04:49 VERBOSE[4502] logger.c: > SAPI: 00 C/R: 0 EA: 0
TEI: 000 EA: 1
Dec 19 14:04:49 VERBOSE[4502] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
N(R): 051 P/F: 1
0 bytes of data
Dec 19 14:04:49 VERBOSE[4502] logger.c: – Restarting T203 counter
Dec 19 14:04:49 VERBOSE[4502] logger.c:
< [ 00 01 01 81 ]
Dec 19 14:04:49 VERBOSE[4502] logger.c:
< Supervisory frame:
Dec 19 14:04:49 VERBOSE[4502] logger.c: < SAPI: 00 C/R: 0 EA: 0
< TEI: 000 EA: 1
Dec 19 14:04:49 VERBOSE[4502] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
< N(R): 064 P/F: 1
< 0 bytes of data
Dec 19 14:04:49 VERBOSE[4502] logger.c: – ACKing all packets from 63 to (but not including) 64
Dec 19 14:04:49 VERBOSE[4502] logger.c: – Since there was nothing left, stopping T200 counter
Dec 19 14:04:49 VERBOSE[4502] logger.c: – Stopping T203 counter since we got an ACK
Dec 19 14:04:49 VERBOSE[4502] logger.c: – Nothing left, starting T203 counter
Dec 19 14:04:49 VERBOSE[4502] logger.c: – Got RR response to our frame
Dec 19 14:04:49 VERBOSE[4502] logger.c: – Restarting T203 counter
Dec 19 14:04:50 DEBUG[8426] channel.c: Didn’t get a frame from channel: SIP/2726-0901db38
Dec 19 14:04:50 DEBUG[8426] channel.c: Bridge stops bridging channels SIP/2726-0901db38 and Zap/3-1
Dec 19 14:04:50 DEBUG[8426] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/3-1
Dec 19 14:04:50 DEBUG[8426] chan_zap.c: Hangup: channel: 3 index = 0, normal = 20, callwait = -1, thirdcall = -1
Dec 19 14:04:50 DEBUG[8426] chan_zap.c: Not yet hungup… Calling hangup once with icause, and clearing call
Dec 19 14:04:50 VERBOSE[8426] logger.c:
[ 00 01 80 66 08 02 00 4a 45 08 02 81 90 ]
Dec 19 14:04:50 VERBOSE[8426] logger.c:
Informational frame:
Dec 19 14:04:50 VERBOSE[8426] logger.c: > SAPI: 00 C/R: 0 EA: 0
TEI: 000 EA: 1
Dec 19 14:04:50 VERBOSE[8426] logger.c: > N(S): 064 0: 0
N(R): 051 P: 0
9 bytes of data
Dec 19 14:04:50 VERBOSE[8426] logger.c: – Restarting T203 counter
Dec 19 14:04:50 VERBOSE[8426] logger.c: Stopping T_203 timer
Dec 19 14:04:50 VERBOSE[8426] logger.c: Starting T_200 timer
Dec 19 14:04:50 VERBOSE[8426] logger.c: > Protocol Discriminator: Q.931 (8) len=9
Dec 19 14:04:50 VERBOSE[8426] logger.c: > Call Ref: len= 2 (reference 74/0x4A) (Originator)
Dec 19 14:04:50 VERBOSE[8426] logger.c: > Message type: DISCONNECT (69)
Dec 19 14:04:50 VERBOSE[8426] logger.c: > [08 02 81 90]
Dec 19 14:04:50 VERBOSE[8426] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1)
Dec 19 14:04:50 VERBOSE[8426] logger.c: > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ]
Dec 19 14:04:50 DEBUG[8426] chan_zap.c: disabled echo cancellation on channel 3
Dec 19 14:04:50 DEBUG[8426] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/3-1
Dec 19 14:04:50 DEBUG[8426] chan_zap.c: Updated conferencing on 3, with 0 conference users
Dec 19 14:04:50 DEBUG[8426] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/3-1
Dec 19 14:04:50 DEBUG[8426] chan_zap.c: disabled echo cancellation on channel 3
Dec 19 14:04:50 VERBOSE[8426] logger.c: – Hungup ‘Zap/3-1’
Dec 19 14:04:50 DEBUG[8426] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Dec 19 14:04:50 VERBOSE[8426] logger.c: == Spawn extension (macro-dialout-trunk, s, 16) exited non-zero on ‘SIP/2726-0901db38’ in macro ‘dialout-trunk’
Dec 19 14:04:50 VERBOSE[8426] logger.c: == Spawn extension (macro-dialout-trunk, s, 16) exited non-zero on ‘SIP/2726-0901db38’
Dec 19 14:04:50 DEBUG[8426] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Dec 19 14:04:50 DEBUG[8426] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2006-12-19 13:59:20’,‘xxxxxxxx’,‘xxxxxxxx’,‘0049xxxxxxxxxx’,‘from-internal’, ‘SIP/2726-0901db38’,‘Zap/3-1’,‘Dial’,‘ZAP/g0/0049xxxxxxxxxx|120|r’,330,321,‘ANSWERED’,3,‘’,‘.376’)
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘xxxxxxxx’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘xxxxxxxx’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘0049xxxxxxxxxx’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘from-internal’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘SIP/2726-0901db38’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘Zap/3-1’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘Dial’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘ZAP/g0/0049xxxxxxxxxx|120|r’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘2006-12-19 13:59:20’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘2006-12-19 13:59:29’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘2006-12-19 14:04:50’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘330’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘321’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘ANSWERED’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘DOCUMENTATION’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘(null)’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘.376’
Dec 19 14:04:50 DEBUG[8426] pbx.c: Function result is ‘(null)’
Dec 19 14:04:50 DEBUG[8426] chan_sip.c: update_call_counter(2726) - decrement call limit counter
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2718
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2710
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2708
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2723
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2713
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2705
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2715
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2707
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2717
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2711
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2725
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2709
Dec 19 14:04:50 VERBOSE[4490] logger.c: Extension Changed 2726 new state Idle for Notify User 2706
Dec 19 14:04:50 VERBOSE[4502] logger.c:

Zaptel.conf :
loadzone = no
defaultzone = no

span=1,1,0,ccs,hdb3,crc4
span=2,0,0,ccs,hdb3,crc4

bchan=1-15
dchan=16
bchan=17-31

bchan=32-46
dchan=47
bchan=48-62

zapata.conf:
[trunkgroups]

[channels]

language=nl
context=from-pstn
switchtype=euroisdn
signalling=pri_cpe
rxwink=300 ; Atlas seems to use long (250ms) winks
;
; Whether or not to do distinctive ring detection on FXO lines
;
;usedistinctiveringdetection=yes
priindication=outofband
usecallerid=yes
hidecallerid=no
callwaiting=yes
usecallingpres=yes
callwaitingcallerid=yes
threewaycalling=yes
transfer=yes
cancallforward=yes
callreturn=yes
echocancel=yes
echocancelwhenbridged=yes
echotraining=yes
echotraining=400
rxgain=1.0
txgain=-1.0
group=0
callgroup=1
pickupgroup=1
immediate=no
busydetect=no
;callprogress=no
channel => 1-15,17-31

group=1
context=from-pstn
switchtype=euroisdn
signalling=pri_net
priindication=outofband
echocancel=yes
echocancelwhenbridged=yes
echotraining=yes
echotraining=400
callgroup=1
pickupgroup=1
immediate=no
busydetect=no
;callprogress=no
channel => 32-46,48-62

kumatel · December 27, 2006, 12:09pm

Hi mdruedal
in your case it looks more like a timer issue. I would suggest to change T203 timer, ask your operator where your PRI lines connected about the right value.

regards
Mathias

micuzzo · January 3, 2007, 1:46pm

Same problem after upgrading to latest version 1.2.14.
Today I got already 5 “Got a FRAME_CONTROL (5) frame on channel Zap”…

Disappointed

mdruedal · January 10, 2007, 8:53pm

Thanks a bunch kumatel, I changed the T203 timer as you suggested, and that did the trick.
For anybody else here’s what I did.:
In Zapata.conf just add this line :
pritimer => t203,30000

the default value is 10000 ms I changed it to 30000ms and that helped. Hope anybody else can use this info…

Topic		Replies	Views
Didn't get a frame from channel Asterisk Support	0	241	January 16, 2007
[help] Got a FRAME_CONTROL (3) frame on channel Zap/14-1 Asterisk Support	0	239	November 7, 2005
Drop calls Asterisk Support	5	256	September 6, 2006
Frame dropped and bridging stopped Asterisk Support	0	199	October 13, 2008
[HELP] Don't know what to do with control frame 15 (TE410P) Asterisk Support	0	179	June 29, 2006

FRAME_CONTROL (5) -- Dropped calls on PRI

Related topics