[Asterisk-Users] False Zap answer problem (Again)

Soner Tari list at kulustur.org
Sat Sep 10 09:58:37 MST 2005 

I've been monitoring this problem for almost a month now. I realized that it 
is more extensive than what I described previously. I can very easily 
replicate this problem on every Zap channel. Following is the senario:

1. Call Zap/5 via say SIP/15 ->
    Zap/5-1 created and starts to ring
2. Call Zap/5 via say SIP/21 ->
    Zap/5-2 created and starts to ring
3. Hangup SIP/15 ->
    Zap/5-1 hungup

Right after this point we have the problem (please see full log below for 
details):
Sep 10 19:22:41 VERBOSE[27367] logger.c:     -- Zap/5-2 answered SIP/21-efcb

When in fact nobody is answering Zap/5-2 !!! And on SIP/21 I hear strange 
ringing tone indefinetly, untill I hangup SIP/21.

What the hell is going on here? I don't have any other problem, this system 
is in use for 1.5 month now (Users cannot notice it, because they hangup 
immediately).

Since I can replicate this problem with Zap/6 and Zap/7 also, I tend to 
think that this is not specific to any FXS module. But, of course, it could 
be the TDM PCI card itself. Could this be a bug in chan_zap.c?

Can somebody please confirm that using the same senario this only happens on 
my system with my TDM card, so I don't file a bug report?

Please find below the relevant sections of full log and my previous post,
Thanks,
Soner

Sep 10 19:22:33 DEBUG[27367] chan_sip.c: Checking SIP call limits for device 
15
Sep 10 19:22:33 DEBUG[27367] chan_sip.c: build_route: Contact hop: 
<sip:15 at xxx.xxx.xxx.xxx:51926>
Sep 10 19:22:33 VERBOSE[27367] logger.c:     -- Executing 
Macro("SIP/15-f784", "ichatarama|Zap/5|10") in new stack
Sep 10 19:22:33 VERBOSE[27367] logger.c:     -- Executing 
GotoIf("SIP/15-f784", "=1?200") in new stack
Sep 10 19:22:33 DEBUG[27367] pbx.c: Not taking any branch
Sep 10 19:22:33 VERBOSE[27367] logger.c:     -- Executing 
Dial("SIP/15-f784", "Zap/5|24|rTtWw") in new stack
Sep 10 19:22:33 VERBOSE[27367] logger.c:     -- Called 5
Sep 10 19:22:33 VERBOSE[27367] logger.c:     -- Zap/5-1 is ringing
Sep 10 19:22:34 DEBUG[27367] chan_sip.c: Setting NAT on RTP to 524288
Sep 10 19:22:35 DEBUG[27367] chan_sip.c: Setting NAT on RTP to 524288
Sep 10 19:22:35 DEBUG[27367] chan_sip.c: Checking SIP call limits for device 
21
Sep 10 19:22:35 DEBUG[27367] chan_sip.c: build_route: Contact hop: 
<sip:21 at xxx.xxx.xxx.xxx:46209>
Sep 10 19:22:35 VERBOSE[27367] logger.c:     -- Executing 
Macro("SIP/21-efcb", "ichatarama|Zap/5|10") in new stack
Sep 10 19:22:35 VERBOSE[27367] logger.c:     -- Executing 
GotoIf("SIP/21-efcb", "=1?200") in new stack
Sep 10 19:22:35 DEBUG[27367] pbx.c: Not taking any branch
Sep 10 19:22:35 VERBOSE[27367] logger.c:     -- Executing 
Dial("SIP/21-efcb", "Zap/5|24|rTtWw") in new stack
Sep 10 19:22:35 DEBUG[27367] chan_zap.c: Already have a dsp on Zap/5-2?
Sep 10 19:22:35 WARNING[27367] chan_zap.c: Spill already exists?!?
Sep 10 19:22:35 VERBOSE[27367] logger.c:     -- Called 5
Sep 10 19:22:35 VERBOSE[27367] logger.c:     -- Zap/5-2 is ringing
Sep 10 19:22:35 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:22:35 DEBUG[27367] chan_zap.c: Got event Ringer Off(11) on channel 
5 (index 0)
Sep 10 19:22:35 VERBOSE[27367] logger.c:     -- Zap/5-1 is ringing
Sep 10 19:22:36 VERBOSE[27367] logger.c:     -- CPE does not support Call 
Waiting Caller*ID.
Sep 10 19:22:39 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:22:39 DEBUG[27367] chan_zap.c: Got event Ringer On(10) on channel 
5 (index 0)
Sep 10 19:22:41 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:22:41 DEBUG[27367] chan_zap.c: Got event Ringer Off(11) on channel 
5 (index 0)
Sep 10 19:22:41 VERBOSE[27367] logger.c:     -- Zap/5-1 is ringing
Sep 10 19:22:41 DEBUG[27367] chan_zap.c: Hangup: channel: 5 index = 0, 
normal = 11, callwait = 35, thirdcall = -1
Sep 10 19:22:41 DEBUG[27367] chan_zap.c: Swapping 1 and 0
Sep 10 19:22:41 DEBUG[27367] chan_zap.c: Released sub 1 of channel 5
Sep 10 19:22:41 VERBOSE[27367] logger.c:     -- Hungup 'Zap/5-1'
Sep 10 19:22:41 DEBUG[27367] app_dial.c: Exiting with DIALSTATUS=CANCEL.
Sep 10 19:22:41 VERBOSE[27367] logger.c:   == Spawn extension 
(macro-ichatarama, s, 2) exited non-zero on 'SIP/15-f784' in macro 
'ichatarama'
Sep 10 19:22:41 VERBOSE[27367] logger.c:   == Spawn extension (ichat, 19, 1) 
exited non-zero on 'SIP/15-f784'
Sep 10 19:22:41 DEBUG[27367] cdr_addon_mysql.c: cdr_mysql: inserting a CDR 
record.
Sep 10 19:22:41 DEBUG[27367] 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 ('2005-09-10 19:22:33','\"Ichat\" <15>','15','19','ichat', 
'SIP/15-f784','Zap/5-1','Dial','Zap/5|24|rTtWw',8,0,'NO 
ANSWER',3,'','1126369353.4')
Sep 10 19:22:41 DEBUG[27367] chan_sip.c: update_user_counter(15) - decrement 
inUse counter
Sep 10 19:22:41 VERBOSE[27367] logger.c:     -- Zap/5-2 answered SIP/21-efcb
Sep 10 19:22:45 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:22:45 DEBUG[27367] chan_zap.c: Got event Ringer On(10) on channel 
5 (index 0)
Sep 10 19:22:47 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:22:47 DEBUG[27367] chan_zap.c: Got event Ringer Off(11) on channel 
5 (index 0)
Sep 10 19:22:47 DEBUG[27367] channel.c: Got a FRAME_CONTROL (3) frame on 
channel Zap/5-2
Sep 10 19:22:47 DEBUG[27367] channel.c: Bridge stops bridging channels 
SIP/21-efcb and Zap/5-2
Sep 10 19:22:47 DEBUG[27367] channel.c: Driver for channel 'SIP/21-efcb' 
does not support indication 3, emulating it
Sep 10 19:22:47 DEBUG[27367] channel.c: Scheduling timer at 160 sample 
intervals
Sep 10 19:22:47 DEBUG[27367] channel.c: Generator got voice, switching to 
phase locked mode
Sep 10 19:22:47 DEBUG[27367] channel.c: Scheduling timer at 0 sample 
intervals
Sep 10 19:22:51 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:22:51 DEBUG[27367] chan_zap.c: Got event Ringer On(10) on channel 
5 (index 0)
Sep 10 19:22:53 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:22:53 DEBUG[27367] chan_zap.c: Got event Ringer Off(11) on channel 
5 (index 0)
Sep 10 19:22:53 DEBUG[27367] channel.c: Got a FRAME_CONTROL (3) frame on 
channel Zap/5-2
Sep 10 19:22:53 DEBUG[27367] channel.c: Bridge stops bridging channels 
SIP/21-efcb and Zap/5-2
Sep 10 19:22:53 DEBUG[27367] channel.c: Driver for channel 'SIP/21-efcb' 
does not support indication 3, emulating it
Sep 10 19:22:53 DEBUG[27367] channel.c: Scheduling timer at 160 sample 
intervals
Sep 10 19:22:53 DEBUG[27367] channel.c: Generator got voice, switching to 
phase locked mode
Sep 10 19:22:53 DEBUG[27367] channel.c: Scheduling timer at 0 sample 
intervals
Sep 10 19:22:56 DEBUG[27367] chan_sip.c: Stopping retransmission on 
'38bc6e546dc2d6cc0e4fc8f50c81012a at 192.168.1.10' of Request 102: Found
Sep 10 19:22:57 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:22:57 DEBUG[27367] chan_zap.c: Got event Ringer On(10) on channel 
5 (index 0)
Sep 10 19:22:59 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:22:59 DEBUG[27367] chan_zap.c: Got event Ringer Off(11) on channel 
5 (index 0)
Sep 10 19:22:59 DEBUG[27367] channel.c: Got a FRAME_CONTROL (3) frame on 
channel Zap/5-2
Sep 10 19:22:59 DEBUG[27367] channel.c: Bridge stops bridging channels 
SIP/21-efcb and Zap/5-2
Sep 10 19:22:59 DEBUG[27367] channel.c: Driver for channel 'SIP/21-efcb' 
does not support indication 3, emulating it
Sep 10 19:22:59 DEBUG[27367] channel.c: Scheduling timer at 160 sample 
intervals
Sep 10 19:22:59 DEBUG[27367] channel.c: Generator got voice, switching to 
phase locked mode
Sep 10 19:22:59 DEBUG[27367] channel.c: Scheduling timer at 0 sample 
intervals
Sep 10 19:23:03 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:23:03 DEBUG[27367] chan_zap.c: Got event Ringer On(10) on channel 
5 (index 0)
Sep 10 19:23:05 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:23:05 DEBUG[27367] chan_zap.c: Got event Ringer Off(11) on channel 
5 (index 0)
Sep 10 19:23:05 DEBUG[27367] channel.c: Got a FRAME_CONTROL (3) frame on 
channel Zap/5-2
Sep 10 19:23:05 DEBUG[27367] channel.c: Bridge stops bridging channels 
SIP/21-efcb and Zap/5-2
Sep 10 19:23:05 DEBUG[27367] channel.c: Driver for channel 'SIP/21-efcb' 
does not support indication 3, emulating it
Sep 10 19:23:05 DEBUG[27367] channel.c: Scheduling timer at 160 sample 
intervals
Sep 10 19:23:05 DEBUG[27367] channel.c: Generator got voice, switching to 
phase locked mode
Sep 10 19:23:05 DEBUG[27367] channel.c: Scheduling timer at 0 sample 
intervals
Sep 10 19:23:09 DEBUG[27367] chan_zap.c: Exception on 11, channel 5
Sep 10 19:23:09 DEBUG[27367] chan_zap.c: Got event Ringer On(10) on channel 
5 (index 0)
Sep 10 19:23:09 DEBUG[27367] channel.c: Scheduling timer at 0 sample 
intervals
Sep 10 19:23:09 DEBUG[27367] channel.c: Didn't get a frame from channel: 
SIP/21-efcb
Sep 10 19:23:09 DEBUG[27367] channel.c: Bridge stops bridging channels 
SIP/21-efcb and Zap/5-2
Sep 10 19:23:09 DEBUG[27367] chan_zap.c: Hangup: channel: 5 index = 0, 
normal = 11, callwait = -1, thirdcall = -1
Sep 10 19:23:09 DEBUG[27367] chan_zap.c: disabled echo cancellation on 
channel 5
Sep 10 19:23:09 DEBUG[27367] chan_zap.c: Set option TDD MODE, value: OFF(0) 
on Zap/5-2
Sep 10 19:23:09 DEBUG[27367] chan_zap.c: Updated conferencing on 5, with 0 
conference users
Sep 10 19:23:09 VERBOSE[27367] logger.c:     -- Hungup 'Zap/5-2'
Sep 10 19:23:09 DEBUG[27367] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Sep 10 19:23:09 VERBOSE[27367] logger.c:   == Spawn extension 
(macro-ichatarama, s, 2) exited non-zero on 'SIP/21-efcb' in macro 
'ichatarama'
Sep 10 19:23:09 VERBOSE[27367] logger.c:   == Spawn extension (ichat, 19, 1) 
exited non-zero on 'SIP/21-efcb'
Sep 10 19:23:09 DEBUG[27367] cdr_addon_mysql.c: cdr_mysql: inserting a CDR 
record.
Sep 10 19:23:09 DEBUG[27367] 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 ('2005-09-10 19:22:35','\"Soner Tari\" <21>','21','19','ichat', 
'SIP/21-efcb','Zap/5-2','Dial','Zap/5|24|rTtWw',34,28,'ANSWERED',3,'','1126369355.6')
Sep 10 19:23:09 DEBUG[27367] chan_sip.c: update_user_counter(21) - decrement 
inUse counter

----- Original Message ----- 
From: "Soner Tari" <list at kulustur.org>
To: "Asterisk Users Mailing List - Non-Commercial Discussion" 
<asterisk-users at lists.digium.com>
Sent: Saturday, August 13, 2005 10:05 PM
Subject: False Zap answer problem


> Hi All,
>
> I am experiencing a very strange problem. I call the FXO channels (Zap/2 
> and 3) almost at the same time, and then hang both up. The operator 
> extension is Zap/6, and after the greeting message Zap/6 starts to ring 
> (there is no disconnect supervision here, and I disabled the busy detect 
> for hangup detection, so the outside lines stay open until Asterisk hangs 
> them up).
>
> As you can see on the following CLI section, when the VoiceMail promt 
> starts to play for Zap/2, the system thinks that Zap/6-2 has answered the 
> Zap/3, when in fact nobody answers it:
>
>    -- Hungup 'Zap/6-1'
>    -- Executing VoiceMail("Zap/2-1", "u0") in new stack
>    -- Playing 'vm-theperson' (language 'tr')
>    -- Zap/6-2 answered Zap/3-1
>
> I can very easily replicate this (did it 3 times).
>
> Where should I look for the source of this problem? Is it the TDM card or 
> the Asterisk? How does Asterisk know if a line has been answered on a TDM 
> card? This seems like some kind of cross-talk between the two FXO 
> channels, but it's really strange. Has anybody had a similar problem?
>
> Of course, the workaround is to use some sort of hangup detection on 
> outside lines, but I was having false hangup problems with busy detect, 
> thus disabled it and noticed this problem (and see my above comment on 
> disconnect supervision here).
>
> I have 2x TDM cards (version E/F) with 3x FXO and 4x FXS modules on each.
>
> Asterisk version is:
> Asterisk CVS-HEAD built by root at asterisk on a i686 running Linux on 
> 2005-08-10 22:55:45 UTC
>
> I have echocancel and echocancelwhenbridged enabled. (Could it be the 
> echocanceller?)
>
> I would appreciate any help,
> Soner
>

More information about the asterisk-users mailing list