[Home]

Summary:ASTERISK-05161: zt_handle_event: Ring/Off-hook in strange state 6 on channel X
Reporter:Serge Vecher (serge-v)Labels:
Date Opened:2005-09-27 11:30:27Date Closed:2011-06-07 14:10:17
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) Corrupt_DID_-_10-12-2005.txt
( 1) Ghost_call_-_09-27-05_no2.txt
( 2) Ghost_call_-_09-29-05.txt
Description:For several months, we are experiencing "ghost calls" on our Asterisk system. By ghost call I mean an incoming call that is not originated from telco (as per telco). There are two variants of suchs calls (as experienced on receiving end): 1) dead silence 2) dialtone. Such calls are always associated with "Ring/off-hook in strange state 6 on channel X" reported on Asterisk console.

Digium TS checked out hardware via loopback-tests and confirmed hardware ok (t/s issue 20438,18031). Telco ran tests and confirmed link ok. When a ghost call appears on Asterisk, they say it's not originated on their side and channel X that has strange state 6 appears to be "locked out."

****** ADDITIONAL INFORMATION ******

Hardware wct100p.

[zaptel.conf]
span=1,1,0,esf,b8zs
e&m=1-8
unused=9-24
loadzone=us
defaultzone=us

[zapata.conf]
language=en
signalling=em_w
callerid=asreceived
uscallerid=yes
echocancel=yes
group-1
channel=>1-8
Comments:By: Serge Vecher (serge-v) 2005-09-27 11:34:24

attached "ghost call - 09-27-05 no2.txt" shows an excerpt from Asterisk console when a latest ghost call happened. There was no activity on Zap/4-1 for at least 15 minutes prior.

I should add, that all other bugs with this following console message: 3407, 2949, 2281, 1814, 811, 136 were mostly closed for "lack of response"


By: Serge Vecher (serge-v) 2005-09-29 14:21:54

"Ghost call - 09-29-05.txt" shows a ghost call that happened right after the hangup on a channel. Dialtone was heard.
By: Matthew Fredrickson (mattf) 2005-09-29 18:58:31

Did you try watching the signaling bits in zttool to see if they change when the "call" comes in?
By: Serge Vecher (serge-v) 2005-09-30 08:56:52

mattf, thanks for the tip. I will run it until "the call" comes in. Also, is there way to run zttool in log mode (in case I miss the call)?
By: Serge Vecher (serge-v) 2005-10-06 13:34:05

Hmm, running zttool in parallel with Asterisk has caused the following to appear on Asterisk console:
[Oct  6 14:12:22] WARNING[8514]: channel.c:741 channel_find_locked: Avoided initial deadlock for '0xb7b06bc0', 10 retries!

After seeing those for pretty much every transaction on Asterisk, I've noticed that Asterisk is really slowing down (delays on call setup, delayed reaction on console, etc.). I've restarted Asterisk - same thing. Then I noticed that zttool was "killed" in another session and Asterisk returned back to normal. I don't know if zttool is meant to run in parallel with Asterisk for prolonged periods of time -- if it is, this is another bug.

On the good note, I didn't see any "ghost calls" for a week now.
By: Serge Vecher (serge-v) 2005-10-07 11:50:08

Ok, a "ghost call" happened today. I ran the zttool and all TX bits were 1 for that channel. RX bits were 0. This happened right after the hangup on a call on the same channel. Unfortunately, I did not have zttool running right when this was happening (for deadlock reasons described above). Even if it was, I would have a chance to spot it -- this behavior is random and last time was spotted on 09/29.

I don't know if this is related, but a /var/log/messages contains the following entry several seconds prior to the "event":

Oct  7 10:01:01 asterisk02 crond(pam_unix)[31487]: session closed for user root
Oct  7 10:38:47 asterisk02 kernel: zaptel Disabled echo canceller because of tone (rx) on channel 1

Where can we go from here?


By: Serge Vecher (serge-v) 2005-10-12 10:32:08

This may shed some more light on this, attached file "Corrupt DID - 10-12-2005.txt" shows a corrupt DID being reported on console 7642383·©», should be 7642383. No ring/off-hook was reported this time, I also did not get dialtone, but beeps at 2 sec intervals. With the "ghost calls" that produce dialtone, I did notice they always came into "s" extension.
By: Serge Vecher (serge-v) 2005-11-12 11:33:52.000-0600

Will update to RC2 and report back here. Currently running 10/29 head. I still get these calls at random: sometimes won't see them for days, sometimes will get hit with one every 1/2 hour. Also, the cause seems to be incorrect detection of hangup event, as detailed in "Ghost call - 09-29-05.txt"
By: Serge Vecher (serge-v) 2005-11-17 12:04:45.000-0600

Ok, this may shed some light here: We get a hangup on Zap/3-1, immediately a switch starts: your typical ghost call scenario. Then we get a warning and it is squelched...

[Nov 17 12:54:47]     -- Hungup 'Zap/3-1'
[Nov 17 12:54:47]   == Spawn extension (macro-extexten, s, 1) exited non-zero on 'SIP/107-00b4' in macro 'extexten'
[Nov 17 12:54:47]   == Spawn extension (ldaccess, 17188499757, 1) exited non-zero on 'SIP/107-00b4'
[Nov 17 12:54:47]     -- Executing Hangup("SIP/107-00b4", "") in new stack
[Nov 17 12:54:47]   == Spawn extension (ldaccess, h, 1) exited non-zero on 'SIP/107-00b4'
[Nov 17 12:54:47]     -- Starting simple switch on 'Zap/3-1'
[Nov 17 12:54:48] WARNING[26450]: chan_zap.c:5334 ss_thread: getdtmf on channel 3: Operation now in progress
[Nov 17 12:54:48]     -- Hungup 'Zap/3-1'
asterisk02*CLI>
By: John Biundo (greyhound) 2005-11-18 22:25:42.000-0600

I'll add my experience in case it's related and might shed some light on this problem.

In my case, I have a pstn line coming into the house, and branching to various extensions.  One of these extensions goes into an X100P card on my * box.

If I place an OUTGOING call on a regular analog phone connected directly to the pstn line (shared by *), I sometimes generate one of these "ghost" calls.  I get a "Starting simple switch on 'Zap/1-1'" message on the console, and the call actually progresses through the default Zap/1 context.  I can hear my prompts and IVR, etc. being played back on the channel at the SAME TIME that I'm making an outbound call.

I'll monitor this bug and see if anyone thinks these problems might be related.  I can reproduce this problem almost at will, so I may be able to help tracking it down if someone can provide guidance.
By: Serge Vecher (serge-v) 2005-11-23 11:42:15.000-0600

Still an issue with current CVS HEAD/1.2 -- had this today on console. After hangup.

[Nov 23 12:36:28]     -- Hungup 'Zap/1-1'
[Nov 23 12:36:28]   == Spawn extension (macro-extexten, s, 1) exited non-zero on 'SIP/100-b9dd' in macro 'extexten'
[Nov 23 12:36:28]   == Spawn extension (ldaccess, 19179033234, 1) exited non-zero on 'SIP/100-b9dd'
[Nov 23 12:36:28]     -- Executing Hangup("SIP/100-b9dd", "") in new stack
[Nov 23 12:36:28]   == Spawn extension (ldaccess, h, 1) exited non-zero on 'SIP/100-b9dd'
[Nov 23 12:36:29]     -- Starting simple switch on 'Zap/1-1'
[Nov 23 12:36:34]     -- Executing NoOp("Zap/1-1", "Reached DID s") in new stack
[Nov 23 12:36:34]     -- Executing Goto("Zap/1-1", "2788269|1") in new stack
[Nov 23 12:36:34]     -- Goto (incomingroute,2788269,1)
[Nov 23 12:36:34]     -- Executing NoOp("Zap/1-1", "Reached DID 2788269") in new stack
[Nov 23 12:36:34]     -- Executing Answer("Zap/1-1", "") in new stack
[Nov 23 12:36:34]     -- Executing Macro("Zap/1-1", "stdexten|105|SIP/105") in new stack
[Nov 23 12:36:34]     -- Executing NoOp("Zap/1-1", "extension s@") in new stack
[Nov 23 12:36:34]     -- Executing Dial("Zap/1-1", "SIP/105|20") in new stack
[Nov 23 12:36:34]     -- Called 105
[Nov 23 12:36:34]     -- SIP/105-e3c9 is ringing
[Nov 23 12:36:36] WARNING[11079]: chan_zap.c:3904 zt_handle_event: Ring/Off-hook in strange state 6 on channel 1
[Nov 23 12:36:36]     -- SIP/105-e3c9 answered Zap/1-1
[Nov 23 12:36:45]   == Spawn extension (macro-stdexten, s, 2) exited non-zero on 'Zap/1-1' in macro 'stdexten'
[Nov 23 12:36:45]   == Spawn extension (incomingroute, 2788269, 3) exited non-zero on 'Zap/1-1'
[Nov 23 12:36:45]     -- Executing Hangup("Zap/1-1", "") in new stack
[Nov 23 12:36:45]   == Spawn extension (incomingroute, h, 1) exited non-zero on 'Zap/1-1'
[Nov 23 12:36:45]     -- Hungup 'Zap/1-1'
By: Matthew Fredrickson (mattf) 2006-01-06 09:43:14.000-0600

The only thing left I can think of is to hook up a t-berd to find out what both ends are actually seeing.  I'm closing this for now, this should be better taken with Digium tech support.
By: Matthew Fredrickson (mattf) 2006-01-06 09:45:14.000-0600

Technical support issue.