[Home]

Summary:ASTERISK-05037: [patch] Dial parsing error?
Reporter:drmac (drmac)Labels:
Date Opened:2005-09-09 11:51:51Date Closed:2005-10-04 21:23:34
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Resources/res_agi
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 20050910__debug5173.diff.txt
Description:This seems to happen purely random. And it happens about once a day. I have a SIP Friend (defiend in sip.conf, no realtime) named 'xocommunications'. I do not have an extensions context with the same name.

All incomming calls on PRI Spans 3 & 4 (Zap49 - Zap95) go into the context "copper_routing":

[copper_routing]
       exten => _1XXXXXXXXXX,1,AGI(lcr.php)
       exten => _XXXXXXXXXX,1,AGI(lcr.php)

       exten => _1800XXXXXXX,1,Dial(Zap/R3d/${EXTEN},60)
       exten => _1866XXXXXXX,1,Dial(Zap/R3d/${EXTEN},60)
       exten => _1877XXXXXXX,1,Dial(Zap/R3d/${EXTEN},60)
       exten => _1888XXXXXXX,1,Dial(Zap/R3d/${EXTEN},60)

The AGI takes over and does everything else. Samples are below. To/From numbers don't seem to make a difference. Allow me to repeat again, this is completly random and we pump thru about 10,000 calls per day thru this machine.

If you need debugs or logs or whatever, let me know.

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

Normal/Correct:

   -- Accepting call from '2813312486' to '9798498526' on channel 0/5, span 3
   -- Executing AGI("Zap/53-1", "lcr.php") in new stack
   -- Launched AGI Script /var/lib/asterisk/agi-bin/lcr.php
   -- AGI Script Executing Application: (SetCDRUserfield) Options: (1)
   -- AGI Script Executing Application: (Dial) Options: (SIP/19798498526@xocommunications|60)
   -- Called 19798498526@xocommunications
   -- SIP/xocommunications-0ce2 is ringing
   -- SIP/xocommunications-0ce2 answered Zap/53-1
   -- Channel 0/5, span 3 got hangup request
   -- Hungup 'Zap/53-1'

Bad/Incorrect:

   -- Accepting call from '8322008569' to '2056740255' on channel 0/5, span 3
   -- Executing AGI("Zap/56-1", "lcr.php") in new stack
   -- Launched AGI Script /var/lib/asterisk/agi-bin/lcr.php
   -- AGI Script Executing Application: (SetCDRUserfield) Options: (1)
   -- AGI Script Executing Application: (Dial) Options: (SIP/12056740225@xocommunications|60)
   -- Called 12056740225@xocommunications
Sep  9 10:55:14 NOTICE[12402]: pbx.c:1681 pbx_extension_helper: Cannot find extension context 'xocommunications'
Comments:By: Clod Patry (junky) 2005-09-09 11:58:50

which version of pbx.c (show version files pbx.c) ?
By: drmac (drmac) 2005-09-09 13:18:14

1.269
By: drmac (drmac) 2005-09-09 13:18:44

my apologies..don't know how this got into ADSI category..
By: Tilghman Lesher (tilghman) 2005-09-09 15:52:38

Please apply this patch and upload a backtrace when the system crashes next.  This will help us track down exactly how that routine is getting entered.
By: drmac (drmac) 2005-09-09 16:02:30

you have something a little less destructive? CRASH is unacceptable on this production server.
By: Tilghman Lesher (tilghman) 2005-09-09 16:22:37

Try this one.  This _might_ also crash your server, but it's specifically designed not to.
By: Michael Jerris (mikej) 2005-09-09 16:26:46

it might be useful to commit those logger changes.. that seems quite useful.
By: Tilghman Lesher (tilghman) 2005-09-09 16:35:47

MikeJ:  isn't that a gem?  There's no manpage for it, though, or I would have found it sooner.
By: Tilghman Lesher (tilghman) 2005-09-09 16:45:01

Hang on a few, it's not quite perfect yet.
By: Brian West (bkw918) 2005-09-10 00:10:09

Also its not wise to exec dial inside of your AGI.

/b
By: paradise (paradise) 2005-09-10 04:14:49

>  Also its not wise to exec dial inside of your AGI.

why?
By: Michael Jerris (mikej) 2005-09-10 07:32:38

Because your entire script engine is running in memory the whole time the call is active, alternatively you can set vars in the agi, then return to the dialplan to do the dial, then, if you have additional tasks to do in agi after the call, you can call a dead agi at that point.
By: Tilghman Lesher (tilghman) 2005-09-10 14:38:13

Found the issue with my debug stuff... had to remove gcc optimizations for it to work.  Try this patch now.  It shouldn't crash your machine, as I've tested it on mine.
By: Brian West (bkw918) 2005-09-10 23:13:34

Yep 100 calls up... 100 copies of php running.. Really nice choice eh?

/b
By: Mark Spencer (markster) 2005-09-12 00:23:43

Are you doing frequent reloads on your extensions?
By: drmac (drmac) 2005-09-13 09:45:17

no. maby 1 or 2 reloads a day. Most days there are no reloads.
By: drmac (drmac) 2005-09-15 09:58:40

I have applied the patch and installed the updated asterisk. I prefixed each LOG_WARNING with "BACKTRACE" so I can easily grep thru the log. I will post whatever I get. Might take a few days to get the call volume up.

I guess put this bug on hold (don't close) for the time being until I report back.
By: drmac (drmac) 2005-09-15 10:44:18

Wow. Lot faster than I expected:

Sep 15 10:39:20 WARNING[13076] logger.c: BACKTRACE: Got 2 backtrace records
Sep 15 10:39:20 WARNING[13076] logger.c: BACKTRACE: #0: [080584E4] asterisk(ast_backtrace+0x4a) [0x80584e4]
Sep 15 10:39:20 WARNING[13076] logger.c: BACKTRACE: #1: [00804DEE] /lib/libc.so.6(__clone+0x5e) [0x804dee]
Sep 15 10:39:20 NOTICE[13076] pbx.c: Cannot find extension context 'xocommunications'
Sep 15 10:39:20 WARNING[13076] logger.c: BACKTRACE: Got 2 backtrace records
Sep 15 10:39:20 WARNING[13076] logger.c: BACKTRACE: #0: [080584E4] asterisk(ast_backtrace+0x4a) [0x80584e4]
Sep 15 10:39:20 WARNING[13076] logger.c: BACKTRACE: #1: [00804DEE] /lib/libc.so.6(__clone+0x5e) [0x804dee]

Between Sep 15 10:29:40 and Sep 15 10:39:20, I show 5 duplicates of the 7 above lines.
By: Kevin P. Fleming (kpfleming) 2005-09-25 22:50:29

It doesn't seem that the backtracing code actually provided any useful information in this case.

The 'Called ...' message from app_dial occurs after it has already created the outbound channel via the channel driver, so this doesn't seem to be a parsing problem unless Dial is choosing the wrong channel driver. One thing you could try would be to replace line 1219 with:

ast_verbose(VERBOSE_PREFIX_3 "Called '%s' using '%s'\n", numsubst, tmp->chan->tech->type);

Another thing to try would be to use the alternate SIP dialing format:

Dial(SIP/xocommunications/12056740225|60)
By: drmac (drmac) 2005-09-26 13:50:57

kevin, which file for that change?
By: Kevin P. Fleming (kpfleming) 2005-09-26 14:05:19

app_dial.c :-)
By: drmac (drmac) 2005-09-27 14:47:47

I tried this: Dial(SIP/xocommunications/12056740225|60) and still get the error every now and then. The line that Kevin said to change in app_dial hasn't revealed anything useful. They all say "-- Called 'xocommunications/12564921252' using 'SIP'" even right before I get the backtrace error.

I'm going to (hopefully) switch this to a dialplan-based dealy like Brian suggested and see if that solves it. However, today is my last day here and I'm not sure I will get to it. If I don't get to it I'll post that this can be closed cause nobody else here knows linux, let alone asterisk.
By: Kevin P. Fleming (kpfleming) 2005-09-29 00:06:48

OK, I do not understand how the SIP channel driver could be causing this message to be generated, unless the call is somehow being sent back into your own server, which seems highly unlikely. In fact, nearly all the calls in chan_sip that relate to extension matching are involved in SIP transfers, which is not likely to be involved here.
By: drmac (drmac) 2005-09-29 21:04:57

Unfortunatly I was unable to finish this move. I no longer have access to this asterisk server. I guess this can be closed cause I can no longer provide any useful info.
By: Clod Patry (junky) 2005-10-04 21:22:58

Im closing that one, since reporter has no more access to his server.

If anyone wants to re-open, feel free to ask a marshall for it.

Thanks.