[Asterisk-Users] False Zap answer problem (Again)
Soner Tari
list at kulustur.org
Sun Sep 11 08:06:16 MST 2005
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", "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
More information about the asterisk-users
mailing list