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