[Home]

Summary:ASTERISK-07851: [patch] hanguponpolarityswitch hangs up on incoming call during ring phase
Reporter:Jared Davison (jared)Labels:
Date Opened:2006-10-02 02:17:44Date Closed:2011-06-07 14:03:02
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_zap
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) chan_zap_reverse_polarity_on_ring.patch
( 1) Log_10_annotated.png
( 2) Log_13.png
( 3) Log_14.png
( 4) wctdm_reverse_debug_log_polarity_reverse.patch
Description:I am in Australia and use Telstra as my provider. During the ringing phase of the call I see reversal of polarities, which asterisk interprets incorrectly. It assumes that the polarity reversal during the ring phase means that the caller has hung up. This is definitely not the case. (Telstra may be sending the polarity reversal for good reason during the ring phase, i just don't know what that reason might be though).

Below in (Appendix 1: Zaptel Driver Log) the zaptel driver debug output showing the polarity reversals as they come from the Telstra exchange. In the example, I ring from an outside phone into the the zaptel line and just let it ring... no one inside answers.

When asterisk finds the polarity reversal during this ring phase it does a ast_softhangup(p->owner, AST_SOFTHANGUP_EXPLICIT) of the incoming channel see (Appendix 2:  chan_zap.c source code fragment). I think the purpose of this is so that it will stop ringing extensions that may have started ringing immediately, so that the users wont pick a call which has actually stopped ringing but asterisk hasn't detected that fact yet.

I suspect that other users of the reverseonpolarityswitch feature don't have exchanges that generate these polarity events during the ring phase.

I have made a patch which I have attached that works for my purposes, but I'm not sure how to go about making it work in a more general sense with what I think the existing code is trying to achieve.

I would like to ask how people think this could be improved so that it could be included in the svn trunk without breaking the existing features.

I have 2 ideas:

1) Add a new config option in zapata.conf.

nohanguponpolarityswitchinringphase=yes

2) Some how find an alogithm that detects real hangups during ringing phase rather than just these random reversal pulses.

Any ideas welcome.

Thanks



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

Appendix 1: Zaptel Driver Log
----------

# tail -f /var/log/messages -n 0
Oct  2 16:46:19 iaxw kernel: RING on 2/4!                            --> start ringing
Oct  2 16:46:20 iaxw kernel: 68868487 Polarity reversed (1 -> -1)
Oct  2 16:46:20 iaxw kernel: NO RING on 2/4!
Oct  2 16:46:22 iaxw kernel: 68870648 Polarity reversed (-1 -> 1)
Oct  2 16:46:22 iaxw kernel: RING on 2/4!
Oct  2 16:46:22 iaxw kernel: 68871032 Polarity reversed (1 -> -1)
Oct  2 16:46:23 iaxw kernel: 68871560 Polarity reversed (-1 -> 1)
Oct  2 16:46:23 iaxw kernel: 68871624 Polarity reversed (1 -> -1)
Oct  2 16:46:23 iaxw kernel: NO RING on 2/4!
Oct  2 16:46:25 iaxw kernel: RING on 2/4!
Oct  2 16:46:26 iaxw kernel: 68874296 Polarity reversed (-1 -> 1)
Oct  2 16:46:26 iaxw kernel: 68874600 Polarity reversed (1 -> -1)
Oct  2 16:46:26 iaxw kernel: NO RING on 2/4!
Oct  2 16:46:28 iaxw kernel: RING on 2/4!
Oct  2 16:46:29 iaxw kernel: NO RING on 2/4!
Oct  2 16:46:31 iaxw kernel: RING on 2/4!
Oct  2 16:46:31 iaxw kernel: 68879689 Polarity reversed (-1 -> 1)
Oct  2 16:46:31 iaxw kernel: 68879945 Polarity reversed (1 -> -1)
Oct  2 16:46:32 iaxw kernel: NO RING on 2/4!
Oct  2 16:46:34 iaxw kernel: 68882377 Polarity reversed (-1 -> 1)  --> this is where i actually hangup calling

Appendix 2:  chan_zap.c source code fragment
----------


case ZT_EVENT_POLARITY:
/*
* If we get a Polarity Switch event, check to see
* if we should change the polarity state and
* mark the channel as UP or if this is an indication
* of remote end disconnect.
*/
if (p->polarity == POLARITY_IDLE) {
p->polarity = POLARITY_REV;
if (p->answeronpolarityswitch &&
   ((ast->_state == AST_STATE_DIALING) ||
(ast->_state == AST_STATE_RINGING))) {
ast_log(LOG_DEBUG, "Answering on polarity switch!\n");
ast_setstate(p->owner, AST_STATE_UP);
if (p->hanguponpolarityswitch) {
gettimeofday(&p->polaritydelaytv, NULL);
}
} else
ast_log(LOG_DEBUG, "Ignore switch to REVERSED Polarity on channel %d, state %d\n", p->channel, ast->_state);
}
/* Removed else statement from here as it was preventing hangups from ever happening*/
/* Added AST_STATE_RING in if statement below to deal with calling party hangups that take place when ringing */
if (p->hanguponpolarityswitch &&
(p->polarityonanswerdelay > 0) &&
      (p->polarity == POLARITY_REV) &&
((ast->_state == AST_STATE_UP) /*|| (ast->_state == AST_STATE_RING)*/ ) ) {
                               /* Added log_debug information below to provide a better indication of what is going on */
ast_log(LOG_DEBUG, "Polarity Reversal event occured - DEBUG 1: channel %d, state %d, pol= %d, aonp= %d, honp= %d, pdelay= %d, tv= %d\n", p->channel, ast->_state, p->polarity, p->answeronpolarityswitch, p->hanguponpolarityswitch, p->polarityonanswerdelay, ast_tvdiff_ms(ast_tvnow(), p->polaritydelaytv) );

if (ast_tvdiff_ms(ast_tvnow(), p->polaritydelaytv) > p->polarityonanswerdelay) {
ast_log(LOG_DEBUG, "Polarity Reversal detected and now Hanging up on channel %d\n", p->channel);
ast_softhangup(p->owner, AST_SOFTHANGUP_EXPLICIT);
p->polarity = POLARITY_IDLE;
} else {
ast_log(LOG_DEBUG, "Polarity Reversal detected but NOT hanging up (too close to answer event) on channel %d, state %d\n", p->channel, ast->_state);
}
} else {
p->polarity = POLARITY_IDLE;
ast_log(LOG_DEBUG, "Ignoring Polarity switch to IDLE on channel %d, state %d\n", p->channel, ast->_state);
}
                    /* Added more log_debug information below to provide a better indication of what is going on */
ast_log(LOG_DEBUG, "Polarity Reversal event occured - DEBUG 2: channel %d, state %d, pol= %d, aonp= %d, honp= %d, pdelay= %d, tv= %d\n", p->channel, ast->_state, p->polarity, p->answeronpolarityswitch, p->hanguponpolarityswitch, p->polarityonanswerdelay, ast_tvdiff_ms(ast_tvnow(), p->polaritydelaytv) );
break;
Comments:By: Jared Davison (jared) 2006-10-02 07:26:36

by the way. I have faxed a disclaimer for any future use.
By: Serge Vecher (serge-v) 2006-10-02 10:08:43

need to find out what that reason is ...
By: Jared Davison (jared) 2006-10-02 10:25:54

yes it would be nice to know why... i'm not sure how to go about finding out. any ideas?

Are there any people in the Australian community that I might be able to talk to who could point me in the right direction to find out? (I have no experience with telco gear, don't know anyone in Telstra who is likely to talk sense with me, asterisk is my first introduction to telephony). any ideas how to proceed appreciated.

i have 5 incoming lines from Telstra on this particular system, and they all seem to behave similarly.


By: Jared Davison (jared) 2006-10-02 10:38:31

I have one line at another site about 4km away which is probably connected to a different Telstra exchange. This one seems to work as you would expect... Zaptel driver log below...

This is a differnet asterisk server, but is running the same versions of asterisk 1.2.12.1 and zaptel 1.2.9.1

# tail -f /var/log/messages -n 0
Oct  3 01:33:59 ast2 kernel: RING on 1/1!
Oct  3 01:33:59 ast2 kernel: 1455450600 Polarity reversed (-1 -> 1)
Oct  3 01:34:00 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:02 ast2 kernel: RING on 1/1!
Oct  3 01:34:03 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:05 ast2 kernel: RING on 1/1!
Oct  3 01:34:06 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:08 ast2 kernel: RING on 1/1!
Oct  3 01:34:09 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:11 ast2 kernel: RING on 1/1!
Oct  3 01:34:12 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:14 ast2 kernel: RING on 1/1!
Oct  3 01:34:15 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:17 ast2 kernel: RING on 1/1!
Oct  3 01:34:18 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:20 ast2 kernel: RING on 1/1!
Oct  3 01:34:21 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:23 ast2 kernel: RING on 1/1!
Oct  3 01:34:24 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:26 ast2 kernel: RING on 1/1!
Oct  3 01:34:27 ast2 kernel: NO RING on 1/1!
Oct  3 01:34:29 ast2 kernel: RING on 1/1!
Oct  3 01:34:30 ast2 kernel: 1455466659 Polarity reversed (1 -> -1)
Oct  3 01:34:30 ast2 kernel: NO RING on 1/1!

One difference between the two systems is that the one that is working has a single TDM400P card, whereas the system that is NOT working has 3 TDM400P cards.

I guess I could connect an oscilloscope and see if the problem lines actually have a reversal on them, or if it is some problem that is being brought in by the zaptel driver... I could remove the other cards in the system not working so it only has one card I guess.

I will post my findings.


By: Jared Davison (jared) 2006-10-04 08:44:13

First test I did was to compare two systems running identical versions of the zaptel-1.2.9.1.

There are 2 asterisk systems in this test iaxw & iaxk. They are different brand computers/motherboards, totally different.
iaxw has 3 TDM400P cards and an AVM FritzCard PCI.
        5 FXO modules and 4 FXS modules
iaxk has 1 TDM400P card with 4 FXO modules

I logged the Zaptel kernel logs on both iaxk and iaxw servers.

I connected the telephone line in parallel to both servers, so the same telephone waveform should show the same results in both logs, with same timestamps. I also connected my digital storage oscilloscope (DSO) to the phone line, so i could capture graphically the waveform and see exactly what was going on.

I then rang the line from my mobile phone, and just let it ring without answering for 21 seconds, and then hung up my mobile.

I have attached the DSO capture of a single channel, which shows the DC voltage bias change when the polarity is reversed. See "Log 10 annotated.png" above.

The kernel log results for each machine follow.

Log 10 from iaxw machine:
------------------------
Oct  4 00:41:46 iaxw kernel: 5750295 Polarity reversed (-1 -> 1)
Oct  4 00:41:46 iaxw kernel: RING on 2/1!
Oct  4 00:41:46 iaxw kernel: 5750455 Polarity reversed (1 -> -1)
Oct  4 00:41:47 iaxw kernel: 5750791 Polarity reversed (-1 -> 1)
Oct  4 00:41:47 iaxw kernel: NO RING on 2/1!
Oct  4 00:41:49 iaxw kernel: RING on 2/1!
Oct  4 00:41:50 iaxw kernel: NO RING on 2/1!
Oct  4 00:41:52 iaxw kernel: RING on 2/1!
Oct  4 00:41:53 iaxw kernel: NO RING on 2/1!
Oct  4 00:41:55 iaxw kernel: RING on 2/1!
Oct  4 00:41:56 iaxw kernel: NO RING on 2/1!
Oct  4 00:41:58 iaxw kernel: RING on 2/1!
Oct  4 00:41:59 iaxw kernel: NO RING on 2/1!
Oct  4 00:42:01 iaxw kernel: RING on 2/1!
Oct  4 00:42:02 iaxw kernel: NO RING on 2/1!
Oct  4 00:42:04 iaxw kernel: RING on 2/1!
Oct  4 00:42:05 iaxw kernel: NO RING on 2/1!
Oct  4 00:42:07 iaxw kernel: 5771178 Polarity reversed (1 -> -1)

Log 10 from iaxk machine:
------------------------
Oct  4 00:41:46 iaxk kernel: RING on 1/1!
Oct  4 00:41:46 iaxk kernel: 6243324 Polarity reversed (1 -> -1)
Oct  4 00:41:47 iaxk kernel: 6243553 Polarity reversed (-1 -> 1)
Oct  4 00:41:47 iaxk kernel: 6243586 Polarity reversed (1 -> -1)
Oct  4 00:41:47 iaxk kernel: NO RING on 1/1!
Oct  4 00:41:49 iaxk kernel: 6244913 Polarity reversed (-1 -> 1)
Oct  4 00:41:49 iaxk kernel: RING on 1/1!
Oct  4 00:41:50 iaxk kernel: 6245110 Polarity reversed (1 -> -1)
Oct  4 00:41:50 iaxk kernel: 6245380 Polarity reversed (-1 -> 1)
Oct  4 00:41:50 iaxk kernel: 6245413 Polarity reversed (1 -> -1)
Oct  4 00:41:50 iaxk kernel: NO RING on 1/1!
Oct  4 00:41:52 iaxk kernel: RING on 1/1!
Oct  4 00:41:53 iaxk kernel: 6246740 Polarity reversed (-1 -> 1)
Oct  4 00:41:53 iaxk kernel: 6246937 Polarity reversed (1 -> -1)
Oct  4 00:41:53 iaxk kernel: NO RING on 1/1!
Oct  4 00:41:55 iaxk kernel: RING on 1/1!
Oct  4 00:41:56 iaxk kernel: NO RING on 1/1!
Oct  4 00:41:58 iaxk kernel: RING on 1/1!
Oct  4 00:41:58 iaxk kernel: 6249502 Polarity reversed (-1 -> 1)
Oct  4 00:41:59 iaxk kernel: 6249674 Polarity reversed (1 -> -1)
Oct  4 00:41:59 iaxk kernel: NO RING on 1/1!
Oct  4 00:42:01 iaxk kernel: RING on 1/1!
Oct  4 00:42:02 iaxk kernel: NO RING on 1/1!
Oct  4 00:42:04 iaxk kernel: RING on 1/1!
Oct  4 00:42:05 iaxk kernel: NO RING on 1/1!
Oct  4 00:42:07 iaxk kernel: 6254025 Polarity reversed (-1 -> 1)

Interpretation:
--------------
The times on the servers are synchronised to the same second, so the logs can be matched on a per second basis.

I must have wired the polarities oppositely because the iaxw goes from -1 to 1 (compared with 1 to -1 iaxk). But this difference should not really make any difference ultimately.

You would expect to see identical log outputs with only a single polarity reversal event at the beginning and another at the end. However, both systems have reported polarity reversals at totally different times. iaxk

iaxw detected the polarity reversal before the RING event initially. Following, iaxk reported 6 pairs of polarity reversal events whereas iaxw reported only 2 pairs during the 21 second ringing phase.


By: Serge Vecher (serge-v) 2006-10-04 08:45:11

jared: did you try contacting Digium Technical support -> support@digium.com yet? They should have the expertise to help you, since you are using Zaptel hardware ...
By: Jared Davison (jared) 2006-10-04 08:59:46

Thanks for the idea. i wasn't aware i could contact them. I will contact them.

In the meantime I have done some more observations so I will post them soon too. Then it will all be documented.
By: Jared Davison (jared) 2006-10-04 09:09:51

Another observation: Log 13

This time just working with a single machine, mainly to capture both signals of the waveform. This one by pure fluke it seems only had the correct number polarity reversals 1 pair.

See Log13.png above for waveforms.

Example of it working as it should

Oct  4 22:44:13 iaxw kernel: 78337042 Polarity reversed (-1 -> 1)
Oct  4 22:44:13 iaxw kernel: RING on 2/1!
Oct  4 22:44:14 iaxw kernel: NO RING on 2/1!
Oct  4 22:44:16 iaxw kernel: RING on 2/1!
Oct  4 22:44:17 iaxw kernel: 78341394 Polarity reversed (1 -> -1)
Oct  4 22:44:18 iaxw kernel: NO RING on 2/1!

The oscilloscope waveform shows the entire duration of the call.
By: Jared Davison (jared) 2006-10-04 09:15:27

Log 14

Basically the same sort of test as above with different random results.
This is an example of it not working properly.

Log14.png attached above.

Oct  4 22:49:16 iaxw kernel: 78639805 Polarity reversed (-1 -> 1)
Oct  4 22:49:16 iaxw kernel: RING on 2/1!
Oct  4 22:49:16 iaxw kernel: 78640157 Polarity reversed (1 -> -1)
Oct  4 22:49:16 iaxw kernel: 78640301 Polarity reversed (-1 -> 1)
Oct  4 22:49:17 iaxw kernel: NO RING on 2/1!
Oct  4 22:49:19 iaxw kernel: 78642765 Polarity reversed (1 -> -1)

I will send this stuff to digium support now and see what they think.

I will follow up here what i learn. Thanks
By: Jared Davison (jared) 2006-10-04 22:04:06

I just added a patch file "wctdm_reverse_debug_log_polarity_reverse.patch" to improve with the zaptel debug log.

the log didn't qualify which FXO module the polarity reversal event happened on, so on a system with more than 1 channel you can't tell what's going on when the system is busy.

Old log:
Oct 3 01:33:59 ast2 kernel: 1455450600 Polarity reversed (-1 -> 1)

New log:

Oct  5 12:56:34 iaxw kernel: RING on 2/3!
Oct  5 13:01:41 iaxw kernel: NO RING on 2/3!
Oct  5 13:01:43 iaxw kernel: 129794392 Polarity reversed (-1 -> 1) on 2/3
Oct  5 13:02:04 iaxw kernel: RING on 2/1!
Oct  5 13:02:04 iaxw kernel: 129815929 Polarity reversed (-1 -> 1) on 2/1
Oct  5 13:02:05 iaxw kernel: NO RING on 2/1!
By: Jared Davison (jared) 2006-10-04 22:11:46

btw. "wctdm_reverse_debug_log_polarity_reverse.patch" is for the zaptel-trunk (revision 1497)
By: Nic Bellamy (nic_bellamy) 2006-10-23 05:28:20

The polarity reversal upon ringing is called a "fast guard" or "line seize" - it's used by the exchange to signal to the PBX that this line is about to ring, since the ringing cadence can take quite some time to detect... the idea being, as soon as that reversal is seen, the PBX will know the line is about to ring, and will count it as in-use when selecting an outbound trunk, so we don't try to ring out on a ringing line, inadvertently answering it (this doesn't totally remove the race, but reduces the window from perhaps two seconds down to some tens of milliseconds).

I'm in the process of getting a test line with this enabled so I can make it work on Telecom NZ's "Clear Forward Answer Reversal" lines; I suspect the Telstra version is very similar if not identical.

Telecom NZ spec is PTC107 - "PABX External Port Interface Requirements", available from http://www.telepermit.co.nz/Ptc107.pdf - there may be an updated version of this (it's very old), but I haven't found it yet.

Telstra AU version (downloadable PDF):
http://www.acif.org.au/ACIF_documents/standards/S002_2005

I'm more than happy to work with others on this - to email me, replace underscore with '.' in my Mantis login, and append "at vadacom.co.nz" (how's that for antispamming... muahahaha! ;-)
By: Jared Davison (jared) 2006-10-23 08:16:43

Thanks for finding out what the reason for the signalling is.

I'll chat with you offline and hopefully we can come up with a suitable zaptel driver patch for this.
By: Nic Bellamy (nic_bellamy) 2006-11-14 20:49:02.000-0600

I'm unfortunately _still_ waiting to get polarity reversals enabled on my line here. Gah!

I've just dropped an email to Jared to see how he's getting on.

This bug ain't dead, just sleeping.

Maintainers:
------------

It'd be nice to get the small polarity reveral logging patch into Zaptel 1.2/1.4/trunk regardless of the rest of this bug - it makes diagnosis of all sorts of things much easier (such as the Telco saying "yes, it's enabled" when it's not).
By: Jason Parker (jparker) 2007-07-09 16:05:09

Where do we stand with this now?
By: Jared Davison (jared) 2007-07-09 19:51:35

I posted my experience to:
http://www.voip-info.org/wiki/view/Australia+Asterisk+Details

A wiki page editor has included my comments in the main section of the page confirming that many people have been having difficulty.

I have noticed today there is a "SoloFlyer's Patch" on that wiki page. The solution sounds hopefull. I will try it myself and let you know of its success. The author claims it works without any side effects.

Although I do not recommend chan_zap_reverse_polarity_on_ring.patch, as it has associated problems.

I would however recommend inclusion of "wctdm_reverse_debug_log_polarity_reverse.patch" (this will help future debuggers) as it simply adds which channel is receiving the polarity reversal to the debug log.
By: Jason Parker (jparker) 2007-12-14 14:33:58.000-0600

Per the wiki link posted, the fix here is to just change the polarity debounce, so that we don't detect false positives.