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

Sun, 11 Sep 2005 08:08:39 -0700

I've reported this issue as a bug, and learned that a workaround seems to be disabling callwaiting :(. Since callwaiting was quite helpful on my systems, I'm not happy with this.
Anyone interested can go to issue tracer and follow if a fix will be released soon (ID# 0005188). 


I really tend to think that there is a bug in chan_zap.c, because this 
issue happens only when the first caller hangs up first, never the 
otherwise. I mean if the second caller hangs up first, the first caller 
continues as usual without any problems and reaches to the VoiceMail system 
as expected. Please see below, in this case there is no problem at all:


   -- Executing Dial("SIP/201-e848", "ZAP/1|15|tr") in new stack
   -- Called 1
   -- Zap/1-1 is ringing
   -- Executing Dial("SIP/202-c185", "ZAP/1|15|tr") in new stack
   -- Called 1
   -- Zap/1-2 is ringing
   -- Zap/1-1 is ringing
   -- CPE does not support Call Waiting Caller*ID.
   -- Hungup 'Zap/1-2'

 == Spawn extension (from-internal, 200, 1) exited non-zero on 
'SIP/202-c185'

   -- Zap/1-1 is ringing
   -- Zap/1-1 is ringing
   -- Nobody picked up in 15000 ms
   -- Hungup 'Zap/1-1'
   -- Executing VoiceMail("SIP/201-e848", "[EMAIL PROTECTED]") in new stack
   ....etc.


Please see below example for the problem case where the second caller 
cannot reach at VoiceMail system, but hears ringing indefinately, thus the 
problem. This cannot be the expected behaviour.



I was suspicious about Call Waiting Caller*ID, so I disabled it, but 
nothing changes. Still, I am concerned about it, because the problem 
happens to the Call Waiting (i.e. the second) caller (I mean to the caller 
who causes the Call Waiting for the callee).


What's going on here? Can somebody try and comment please? Any ideas?
Thanks,
Soner


I can replicate this issue on my test system with 1x FXS module too:
   -- Executing Dial("SIP/202-ea85", "ZAP/1|15|tr") in new stack
   -- Called 1
   -- Zap/1-1 is ringing
   -- Zap/1-1 is ringing
   -- Executing Dial("SIP/201-bf73", "ZAP/1|15|tr") in new stack
   -- Called 1
   -- Zap/1-2 is ringing
   -- CPE does not support Call Waiting Caller*ID.
   -- Zap/1-1 is ringing
   -- Hungup 'Zap/1-1'

 == Spawn extension (from-internal, 200, 1) exited non-zero on 
'SIP/202-ea85'

   -- Zap/1-2 answered SIP/201-bf73


When the channels are internal as they are above, it looks like a 
nonissue and seems like an expected behaviour.



But if the call is from external (FXO lines), hangup detection using busy 
detect is affected, and my PSTN lines stay open and Asterisk keeps 
attempting to bridge the 2 channels (FXO and FXS).



Can somebody comment please? Should this be the expected behaviour of 
chan_zap?

Soner


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:[EMAIL PROTECTED]: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:[EMAIL PROTECTED]: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 
'[EMAIL PROTECTED]' 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" <[EMAIL PROTECTED]>
To: "Asterisk Users Mailing List - Non-Commercial Discussion" 
<asterisk-users@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 [EMAIL PROTECTED] 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


_______________________________________________
--Bandwidth and Colocation sponsored by Easynews.com --

Asterisk-Users mailing list
Asterisk-Users@lists.digium.com
http://lists.digium.com/mailman/listinfo/asterisk-users
To UNSUBSCRIBE or update options visit:
  http://lists.digium.com/mailman/listinfo/asterisk-users














    











					Reply via email to