[Asterisk-Users] False Zap answer problem (Again)
Soner Tari
list at kulustur.org
Sat Sep 10 11:43:21 MST 2005
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", "u200 at default") 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: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
>>>
>>
>> _______________________________________________
>> --Bandwidth and Colocation sponsored by Easynews.com --
>>
>> Asterisk-Users mailing list
>> Asterisk-Users at 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
>
> _______________________________________________
> --Bandwidth and Colocation sponsored by Easynews.com --
>
> Asterisk-Users mailing list
> Asterisk-Users at 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
More information about the asterisk-users
mailing list