[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