[Home]

Summary:ASTERISK-20082: Phantom calls open analog DAHDI switch and send dialplan into loop, causing /var to fill up with logs
Reporter:Ryan Steele (rgs)Labels:
Date Opened:2012-07-02 09:08:03Date Closed:2012-07-09 17:51:46
Priority:CriticalRegression?
Status:Closed/CompleteComponents:Core/Channels
Versions:1.8.11.1 Frequency of
Occurrence		Frequent
Related
Issues:
Environment:Ubuntu Server 10.04 (Lucid) root@phone1:~# uname -a Linux phone1 2.6.32-40-server #87-Ubuntu SMP Tue Mar 6 02:10:02 UTC 2012 x86_64 GNU/Linux ii asterisk 1:1.8.11.1-1digium1~lucid Open Source Private Branch Exchange (PBX) ii asterisk-config 1:1.8.11.1-1digium1~lucid Configuration files for Asterisk ii asterisk-core-sounds-en-gsm 1.4.21-1digium1~lucid asterisk PBX sound files - English/gsm ii asterisk-dahdi 1:1.8.11.1-1digium1~lucid DAHDI devices support for the Asterisk PBX ii asterisk-dev 1:1.8.11.1-1digium1~lucid Development files for Asterisk ii asterisk-doc 1:1.8.11.1-1digium1~lucid Source code documentation for Asterisk ii asterisk-moh-opsound-wav 2.03-1digium1~lucid asterisk extra sound files - English/wav ii asterisk-sounds-extra 1.4.9-1 Additional sound files for the Asterisk PBX ii asterisk-voicemail 1:1.8.11.1-1digium1~lucid simple voicemail support for the Asterisk PB ii dahdi 1:2.2.1-0ubuntu2 utilities for using the DAHDI kernel modules ii dahdi-dkms 1:2.2.1+dfsg-1ubuntu2 DAHDI telephony interface (dkms kernel drive ii dahdi-linux 1:2.2.1+dfsg-1ubuntu2 DAHDI telephony interface - Linux userspace Attachments:( 0) asterisk_debug_log-07.03.2012.txt
( 1) chan_dahdi.conf
( 2) init.conf
( 3) modules
( 4) system.conf
Description:After starting Asterisk, it takes (at most) an hour or two before I seeing calls come in on the analog lines, even when no legitimate call is actually coming in.  (Note: I can make successful calls on the analog channels, and they do not appear to cause this issue).  For some reason, only these phantom calls trigger the "chan_sip.c: This function can only be used on SIP channels." error, at which point the dialplan goes into an endless loop:


[Jun 21 13:00:35] VERBOSE[26635] sig_analog.c:     -- Starting simple switch on 'DAHDI/1-1'
[Jun 21 13:00:41] WARNING[26635] chan_sip.c: This function can only be used on SIP channels.
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Executing [s@inbound:1] Set("DAHDI/1-1", "TOLLFREENUM=") in new stack
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Executing [s@inbound:2] NoOp("DAHDI/1-1", ""Toll free number dialed is: "") in new stack
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Executing [s@inbound:3] Goto("DAHDI/1-1", ",1") in new stack
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Goto (inbound,s,1)
[Jun 21 13:00:41] WARNING[26635] chan_sip.c: This function can only be used on SIP channels.
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Executing [s@inbound:1] Set("DAHDI/1-1", "TOLLFREENUM=") in new stack
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Executing [s@inbound:2] NoOp("DAHDI/1-1", ""Toll free number dialed is: "") in new stack
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Executing [s@inbound:3] Goto("DAHDI/1-1", ",1") in new stack
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Goto (inbound,s,1)
[Jun 21 13:00:41] WARNING[26635] chan_sip.c: This function can only be used on SIP channels.
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Executing [s@inbound:1] Set("DAHDI/1-1", "TOLLFREENUM=") in new stack
[Jun 21 13:00:41] VERBOSE[26635] pbx.c:     -- Executing [s@inbound:2] NoOp("DAHDI/1-1", ""Toll free number dialed is: "") in new stack


This repeats endlessly until /var fills up, which causes Asterisk to crash, and kills performance until it does. Again, there is no call coming in to trigger this. I turned down the rxgain to 0 as a test (since doing so makes the phone audio kind of quiet), but I am still seeing this with a regularity that makes it unfeasible to move to these new phone servers (we are currently running an ancient 1.4, and are ready to move to 1.8 once this issue is squashed).
Comments:By: Matt Jordan (mjordan) 2012-07-02 09:41:53.528-0500

We require a complete debug log to help triage the issue. This document will provide instructions on how to collect debugging logs from an Asterisk machine for the purpose of helping bug marshals troubleshoot an issue: https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

Please also provide your DAHDI, chan_dahdi, and sip configuration files.
By: Ryan Steele (rgs) 2012-07-02 09:52:31.782-0500

No problem, I will try to get that back to you today, or at least by tomorrow, before we hit the July 4th holiday.
By: Rusty Newton (rnewton) 2012-07-02 14:36:56.835-0500

Thanks! Be sure to read https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines and attach any debug or output as an attachment.
By: Richard Mudgett (rmudgett) 2012-07-05 11:08:39.871-0500

{noformat}
[Jul  3 10:26:29] DEBUG[20165] pbx.c: Evaluating 'SIP_HEADER(TO):5' (from 'SIP_HEADER(TO):5}' len 16)
[Jul  3 10:26:29] WARNING[20165] chan_sip.c: This function can only be used on SIP channels.
[Jul  3 10:26:29] DEBUG[20165] pbx.c: Function result is '(null)'
[Jul  3 10:26:29] DEBUG[20165] pbx.c: Function result is ''
[Jul  3 10:26:29] DEBUG[20165] pbx.c: Launching 'Set'
[Jul  3 10:26:29] VERBOSE[20165] pbx.c:     -- Executing [s@inbound:1] Set("DAHDI/1-1", "TOLLFREENUM=") in new stack
[Jul  3 10:26:29] DEBUG[20165] pbx.c: Result of 'TOLLFREENUM' is ''
[Jul  3 10:26:29] DEBUG[20165] pbx.c: Launching 'NoOp'
[Jul  3 10:26:29] VERBOSE[20165] pbx.c:     -- Executing [s@inbound:2] NoOp("DAHDI/1-1", ""Toll free number dialed is: "") in new stack
[Jul  3 10:26:29] DEBUG[20165] pbx.c: Result of 'TOLLFREENUM' is ''
[Jul  3 10:26:29] DEBUG[20165] pbx.c: Launching 'Goto'
[Jul  3 10:26:29] VERBOSE[20165] pbx.c:     -- Executing [s@inbound:3] Goto("DAHDI/1-1", ",1") in new stack
[Jul  3 10:26:29] VERBOSE[20165] pbx.c:     -- Goto (inbound,s,1)
{noformat}

Your dialplan appears to be evaluating a SIP specific function "SIP_HEADER(TO):5" on a DAHDI channel.  Your dialplan then appears to be doing a computed goto using an empty channel variable.  This explains your infinite loop.  It does not explain how it got started though.

FYI: When you are done supplying feedback, you need to send the issue back or it can fall off the radar waiting for you to complete your feedback response.
By: Ryan Steele (rgs) 2012-07-05 13:54:18.380-0500

As far as it getting started is concerned, the description kind of explains what's happening, but not why.  A simple switch gets created via the POTS line on the telephony card (perhaps the telco is testing the line to see if anything is on the other end?  not unheard of...), and for some reason it acts like it's not getting converted from analog -> digital before running the call through the dialplan.  I have no idea how that actually happens though - I've not got much frame of reference for how the signal is supposed to be converted by the card and passed to DAHDI.  Does DAHDI make any assumptions about the type of call, or should the signal already be digital by that point?
By: Ryan Steele (rgs) 2012-07-05 13:57:16.066-0500

In the interim, is there any way I can inspect the call type in the dialplan, to prevent executing SIP functions on non-SIP channels?
By: Richard Mudgett (rmudgett) 2012-07-05 16:24:32.798-0500

You can separate incoming calls by technology based upon what context you configure the technology to start incoming calls in the dialplan.  You could also look at the CHANNEL(name) start to determine the technology  (e.g., "DAHDI/" and "SIP/").  There are likely other methods you could use to distinguish where the calls came from.

You have not supplied your chan_dahdi.conf file and any file that is included by it to see how you have configured the DAHDI/1 channel.  Are you expecting to have incoming calls on this channel?  Based upon what I am seeing in the debug log and the code it does not look like your dialplan can handle any incoming calls from this channel.

This issue is looking more like a configuration issue than an actual bug in Asterisk.
By: Ryan Steele (rgs) 2012-07-06 07:28:30.693-0500

I will upload my DAHDI configs momentarily; I meant to do so earlier but forgot.  In any case, a channel is being opened with no actual call coming in - how is that a config issue?  When actual calls come in over the analog channel, everything works fine.  I agree that the infinite loop can be solved by modifying the dialplan, but the phantom call itself should never occur in the first place, and I just don't see how a misconfiguration could be a catalyst for that.  Keep in mind I haven't raised the tx or rx gain, so it's not like some random noise is getting amplified and triggering this behavior.
By: Richard Mudgett (rmudgett) 2012-07-06 11:20:39.687-0500

Your chan_dahdi.conf creates channels and then continues to set more options.  Since you only have one channel line, any option set after it has no effect.

{noformat}
; Each channel consists of the channel number or range.  It inherits the
; parameters that were specified above its declaration.
;
;
;callerid="Green Phone"<(256) 428-6121>
;channel => 1
{noformat}

You can use
{noformat}grep -v "^;" chan_dahdi.conf{noformat}
to remove most of the comment lines to quickly see the active configuration.

I'm not so sure that your phantom calls are all that phantom.  Your debug trace and the code indicated that the phantom call was triggered by a ring signal.  There are times where a line will ring only once but nobody is there.  Either the telco is testing the line or the caller hung up the call right after dialing.  Since you are using analog lines, you can hook an analog phone in parallel to test if you are getting a single ring when a phantom call happens.
By: Rusty Newton (rnewton) 2012-07-06 16:57:14.806-0500


{noformat}
exten => s,1,Set(TOLLFREENUM=${CUT(SIP_HEADER(TO):5,@,1)})
exten => s,n,NoOp("Toll free number dialed is: ${TOLLFREENUM}")
exten => s,n,Goto(${TOLLFREENUM},1)
{noformat}

With the dialplan above corrected so that it can handle DAHDI channels appropriately, how do the suspected phantom calls behave?
By: Ryan Steele (rgs) 2012-07-09 05:38:20.752-0500

{code}
exten => s,1,Set(TOLLFREENUM=${CUT(SIP_HEADER(TO):5,@,1)})
exten => s,n,NoOp("Toll free number dialed is: ${TOLLFREENUM}")
exten => s,n,Goto(${TOLLFREENUM},1)

With the dialplan above corrected so that it can handle DAHDI channels appropriately, how do the suspected phantom calls behave?
{code}

I haven't had the chance to modify it yet.  I'm hoping to get some time this week to develop and test something, since I'm gone next week for my honeymoon.  I'll report back as soon as I have something that I think works.  

In the meantime - any ideas as to how I could prevent Asterisk from picking up the call in the first place?  I'm sure there's some elegant way to distinguish these 'test signals' being sent by the telco (which is kind of what I've suspected all along) from actual calls.
By: Richard Mudgett (rmudgett) 2012-07-09 10:36:36.863-0500

A detected ring is still a ring and must be treated as an incoming call.  The only way to tell the difference between calls is ring cadence, which has other purposes.
By: Rusty Newton (rnewton) 2012-07-09 17:51:15.638-0500

Contact the manufacturer of your hardware interface. If its a Digium card under support, our support guys would provide you ways to verify whether the call is a "real" call or not. These methods may differ depending on your particular card.

From your dialplan, any analog "call" (real or not) would get stuck in your loop. Any analog call without DID will be sent to the s extension.

I'm closing this as we can plainly see a dialplan configuration issue, and this is not the appropriate forum to troubleshoot a potential issue with your analog line, or analog interface hardware.

Please pursue any further questions about dialplan configuration on the wiki, forums or mailing list, and any questions about the analog interface with your manufacturer or other users of that interface. If you gather evidence of a bug after that, please request a re-open or submit a new report.

Thanks!
By: Ryan Steele (rgs) 2012-07-10 07:01:50.658-0500

Rusty - I have already stated that regular analog calls do work with this dialplan, and do not get stuck in any kind of loop.  It's definitely only these weird non-legitimate calls, which always have no caller ID and somehow trick Asterisk into thinking they should have SIP functions applied to them.  The loop is only due to the fact that these are not legitimate calls.  Sure, the dialplan could be modified to prevent the loop, but the calls shouldn't be picked up, and even if they are, Asterisk shouldn't be attempting to apply SIP functions to these channels.  The fact that it doesn't when a valid call comes in should be enough to show this is more than just a dialplan issue, no?
By: Ryan Steele (rgs) 2012-07-10 07:04:17.155-0500

I should also note that this does not occur with Asterisk 1.4, using the same dialplan.  The only difference is the version of Asterisk and the fact that the 1.4 installation uses Zaptel instead of DAHDI.  The hardware, analog lines, telco, and configuration are all otherwise identical.
By: Rusty Newton (rnewton) 2012-07-19 16:31:10.443-0500

bq. Rusty - I have already stated that regular analog calls do work with this dialplan, and do not get stuck in any kind of loop. It's definitely only these weird non-legitimate calls, which always have no caller ID

Based on your dialplan alone I don't understand how any DAHDI based call without DID(not CallerID) would make it out of the loop you constructed without other factors involved besides just that dialplan. You would need to post CLI debug showing a working analog call being answered for us to understand the call path better. Never-the-less, that loop just adds complication, so it should be fixed before troubleshooting any further.

bq. and somehow trick Asterisk into thinking they should have SIP functions applied to them.

You have instructed Asterisk, via dialplan, to CUT a SIP_HEADER on a DAHDI channel. Asterisk is attempting to do what it has been instructed to do.

bq. The loop is only due to the fact that these are not legitimate calls.

If a DAHDI channel, legitimate call or not, enters the three lines of dialplan I referenced on 06/Jul/12 4:57 PM, and Asterisk is behaving appropriately - once hitting the Goto, it should always Goto s,n,1 as ${TOLLFREENUM} would never be populated, seeing as there is no SIP headers on a DAHDI channel. *Any* DAHDI channel should not break out of that loop based on the dialplan alone. Are you doing something AMI or another method to send that channel elsewhere?

bq. Sure, the dialplan could be modified to prevent the loop, but the calls shouldn't be picked up, and even if they are, Asterisk shouldn't be attempting to apply SIP functions to these channels. The fact that it doesn't when a valid call comes in should be enough to show this is more than just a dialplan issue, no?

If DAHDI tells Asterisk that a ring is occurring , it will pick it up. You need to find out whether a ring is occurring on the line or not, and if there is a problem with the line, the board or your driver before looking further into Asterisk.

Asterisk is telling you the SIP function can only be applied on a SIP channel, because your dialplan inappropriately instructs Asterisk to apply the function to a DAHDI channel.

The debug and dialplan we have here does not indicate an issue outside of dialplan. The possibility exists, and we are attempting to point you in the right direction so you can troubleshoot the line, board and driver.

Please contact the support group for the manufacturer of your board and they should help troubleshoot whether there is an issue with the line, board or driver.  

bq. I should also note that this does not occur with Asterisk 1.4, using the same dialplan. The only difference is the version of Asterisk and the fact that the 1.4 installation uses Zaptel instead of DAHDI. The hardware, analog lines, telco, and configuration are all otherwise identical.

Thanks for additional information, but it working in an extremely old version of Asterisk and DAHDI doesn't help us out here.

Again, we are trying to help you solve this issue. Contacting your board vendor will get you on the right path. If this is a Digium board, please call 1-256-428-6000, option 2 and 2 to get to support.