[Home]

Summary:ASTERISK-16677: [patch] Crash, possibly with MYSQL() or with GotoIfTime() inside a Macro()
Reporter:Jonas Kellens (jonaskellens)Labels:
Date Opened:2010-09-14 13:24:54Date Closed:2011-07-27 13:10:29
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) backtrace.txt
( 1) issue17992_1.diff
Description:I am not restarting or reloading Asterisk, but it does it on its own !!

PBX Core settings
-----------------
 Version:                     1.6.2.11
 Build Options:               LOADABLE_MODULES
 Maximum calls:               Not set
 Maximum open file handles:   Not set
 Verbosity:                   25
 Debug level:                 0
 Maximum load average:        0.000000
 Minimum free memory:         0 MB
 Startup time:                13:25:30
 Last reload time:            13:25:30


PBX Core settings
-----------------
 Version:                     1.6.2.11
 Build Options:               LOADABLE_MODULES
 Maximum calls:               Not set
 Maximum open file handles:   Not set
 Verbosity:                   25
 Debug level:                 0
 Maximum load average:        0.000000
 Minimum free memory:         0 MB
 Startup time:                19:52:14
 Last reload time:            19:52:14

Is this a really really major bug ?!


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

I notice this because I use SIP realtime and after I do a SIP reload all my registrations are lost or the SIP peers are indicated as "UNREACHABLE". They then register again slowly...

I noticed that my SIP peers were re-registering again and so there had to be some kind of reload or restart. But I did not issue one !!

Then I look at "show core settings" and notice the difference in 'Last reload time'.

Using asterisk 1.6.2.11 on CentOS 5.5
Comments:By: Jonas Kellens (jonaskellens) 2010-09-14 13:32:44

And again !! Without me doing anything !!

PBX Core settings
-----------------
 Version:                     1.6.2.11
 Build Options:               LOADABLE_MODULES
 Maximum calls:               Not set
 Maximum open file handles:   Not set
 Verbosity:                   25
 Debug level:                 0
 Maximum load average:        0.000000
 Minimum free memory:         0 MB
 Startup time:                20:24:51
 Last reload time:            20:24:51
By: Leif Madsen (lmadsen) 2010-09-14 14:44:01

This sounds like either a crash, or some script executing a restart of some sort.

You'll need to provide console output and logging when this occurs. If this is a crash, then I suggest you read the backtrace documentation located in the doc/ directory of your Asterisk source.


~~~~~~~~~~~~


Thank you for your bug report. In order to move your issue forward, we require a backtrace from the core file produced after the crash. Please see the doc/backtrace.txt file in your Asterisk source directory.

Also, be sure you have DONT_OPTIMIZE enabled in menuselect within the Compiler Flags section, then:

make install

after enabling, reproduce the crash, and then execute the instructions in doc/backtrace.txt.

When complete, attach that file to this issue report. Thanks!
By: Jonas Kellens (jonaskellens) 2010-09-15 04:10:40

I have recompiled a version lower : asterisk 1.6.2.10, but this morning I saw the same problem.

It occurred at 10:11:11.

In asterisk.conf I have :

;maxcalls = 10 ; Maximum amount of calls allowed
;maxload = 0.9 ; Asterisk stops accepting new calls if the load average exceed this limit
;maxfiles = 1000 ; Maximum amount of openfiles
;minmemfree = 1 ; in MBs, Asterisk stops accepting new calls if the amount of free memory falls below this watermark

dumpcore = yes ; Dump core on crash (same as -g at startup)

But I have no core.pid in /etc/asterisk (core dump as suggested on mailinglist)

This is my debug log with debg level 9 :

...
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'NoOp'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Function result is '252227026'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Set'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Macro'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Connect connid localhost username passwd Asterisk
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: setting var 'connid' to value '1'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Query resultid 1 SELECT klantID, vakantieID, feestdagID, kantoorurenID, routeID, Accountco
deIN, backupID from DID where DID=252482233
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: setting var 'resultid' to value '2'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Fetch fetchid 2 klantID vakantieID feestdagenID kantoorurenID routeID AccountcodeIN BACKUP
ID
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: ast_MYSQL_fetch: numFields=7
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: setting var 'fetchid' to value '1'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'NoOp'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: NoOp
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Clear 2
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Disconnect 1
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MacroExit'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Macro'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Connect connid localhost username passwd Asterisk
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: setting var 'connid' to value '1'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'

[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Query resultid 1 SELECT KNUMMER , vmcontext , accountcode_out , hostedformule , mohclass F
ROM AstDB where klantID=50
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: setting var 'resultid' to value '2'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Fetch fetchid 2 KNUMMER VMCONTEXT ACCOUT FORMULE MOHCLASS
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: ast_MYSQL_fetch: numFields=5
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: setting var 'fetchid' to value '1'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'NoOp'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: NoOp
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Clear 2
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Disconnect 1
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MacroExit'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Set'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'SetMusicOnHold'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Set'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Macro'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'NoOp'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: NoOp
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Goto'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: GoTo
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Set'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: Set
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MacroExit'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Function result is '50'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'NoOp'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Function result is '1'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'NoOp'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Function result is '1'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Expression result is '0'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Not taking any branch
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Return'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Goto'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'NoOp'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Set'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Function result is '"252471126" <252471126>'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Set'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Goto'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'Macro'
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Connect connid localhost username passwd Asterisk
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: setting var 'connid' to value '1'
[Sep 15 10:11:11] DEBUG[12353] app_macro.c: Executed application: MYSQL
[Sep 15 10:11:11] DEBUG[12353] pbx.c: Launching 'MYSQL'
[Sep 15 10:11:11] DEBUG[12353] app_addon_sql_mysql.c: MYSQL: data=Query resultid 1 SELECT ast1 , ast2 , na , naID FROM vakantiedata where ID=58
[Sep 15 10:11:22] DEBUG[12362] xmldoc.c: Cannot find variable 'IAXPEER' in tree 'description'
[Sep 15 10:11:22] DEBUG[12362] xmldoc.c: Cannot find variable 'IAXVAR' in tree 'description'
[Sep 15 10:11:22] DEBUG[12362] xmldoc.c: Cannot find variable 'AGENT' in tree 'description'
[Sep 15 10:11:23] DEBUG[12362] xmldoc.c: Cannot find variable 'SIPPEER' in tree 'description'
[Sep 15 10:11:23] DEBUG[12362] xmldoc.c: Cannot find variable 'SIPCHANINFO' in tree 'description'
[Sep 15 10:11:37] DEBUG[12434] xmldoc.c: Cannot find variable 'IAXPEER' in tree 'description'
[Sep 15 10:11:37] DEBUG[12434] xmldoc.c: Cannot find variable 'IAXVAR' in tree 'description'
[Sep 15 10:11:37] DEBUG[12434] xmldoc.c: Cannot find variable 'AGENT' in tree 'description'
[Sep 15 10:11:37] DEBUG[12434] xmldoc.c: Cannot find variable 'SIPPEER' in tree 'description'
[Sep 15 10:11:37] DEBUG[12434] xmldoc.c: Cannot find variable 'SIPCHANINFO' in tree 'description'
[Sep 15 10:15:47] DEBUG[12773] xmldoc.c: Cannot find variable 'IAXPEER' in tree 'description'
...


Restarting my CentOS server seems to bring some stability for about 14 hours...


By: Jonas Kellens (jonaskellens) 2010-09-15 04:43:38

Asterisk seems to have problems with the following :

[Sep 15 11:16:32]     -- Goto (azura,pbx,1)
[Sep 15 11:16:32]     -- Executing [pbx@azura:1] NoOp("SIP/INTERTELin-00000000", "22480333 = pbx formule") in new stack
[Sep 15 11:16:32]     -- Executing [pbx@azura:2] Set("SIP/INTERTELin-00000000", "CDR(accountcode)=AZURAin") in new stack
[Sep 15 11:16:32]     -- Executing [pbx@azura:3] Set("SIP/INTERTELin-00000000", "BRON="473555006" <473555006>") in new stack
[Sep 15 11:16:32]     -- Executing [pbx@azura:4] Goto("SIP/INTERTELin-00000000", "vakantie") in new stack
[Sep 15 11:16:32]     -- Goto (azura,pbx,5)
[Sep 15 11:16:32]     -- Executing [pbx@azura:5] Macro("SIP/INTERTELin-00000000", "vakantie,58") in new stack
[Sep 15 11:16:32]     -- Executing [s@macro-vakantie:1] MYSQL("SIP/INTERTELin-00000000", "Connect connid localhost username passwd AsteriskHosted") in new stack
[Sep 15 11:16:32]     -- Executing [s@macro-vakantie:2] MYSQL("SIP/INTERTELin-00000000", "Query resultid 1 SELECT ast1 , ast2 , na , naID FROM vakantiedata where ID=58") in new stack
vps2301*CLI>
Disconnected from Asterisk server
[Sep 15 11:16:32] Executing last minute cleanups


This is the dialplan :

[macro-vakantie]
exten => s,1,MYSQL(Connect connid localhost username passwd AsteriskHosted)
exten => s,n,MYSQL(Query resultid ${connid} SELECT ast1 , ast2 , na , naID FROM vakantiedata where ID=${ARG1})
exten => s,n,MYSQL(Fetch fetchid ${resultid} AST1 AST2 NA naID )
exten => s,n,NoOp(vakantie-ast1 = ${AST1} vakantie-ast2 = ${AST2} na = ${NA} naID = ${naID})
exten => s,n,MYSQL(Clear ${resultid})
exten => s,n,MYSQL(Disconnect ${connid})

exten => s,n,NoOp(fetchid = ${fetchid})
exten => s,n,GoToIf($["${fetchid}"=="0"]?exit)

exten => s,n,NoOp()
exten => s,n,GoToIfTime(${AST1}?opvakantie)
exten => s,n,GoToIfTime(${AST2}?opvakantie)

exten => s,n(exit),NoOp()
exten => s,n,Set(vakantieresult=continue)
exten => s,n,MacroExit

exten => s,n(opvakantie),NoOp(op vakantie !)
exten => s,n,GoToIf($["${NA}"="hangup"]?hangup:route)


Anything abnormal ?


By: Leif Madsen (lmadsen) 2010-09-15 13:05:49

Where is your backtrace as requested?
By: Jonas Kellens (jonaskellens) 2010-09-17 09:21:25

Hello,

I have compiled with DONT_OPTIMIZE.

When generating the backtrace, I get the following output now :

[root@asterisk16 tmp]# ls
core.asterisk16.jocan.local-2010-09-17T10:03:15+0200
[root@asterisk16 tmp]# gdb -se "/usr/sbin/asterisk" -ex "bt full" -ex
"thread apply all bt" --batch -c
/tmp/core.asterisk16.jocan.local-2010-09-17T10\:03\:15+0200 >
/tmp/backtrace.txt

warning: exec file is newer than core file.

warning: .dynamic section for "/lib/libcrypt.so.1" is not at the
expected address

warning: difference appears to be caused by prelink, adjusting expectations

warning: .dynamic section for "/lib/libnsl.so.1" is not at the expected
address

warning: difference appears to be caused by prelink, adjusting expectations


I hope this means the backtrace is still OK ?!

It is uploaded...
By: Jonas Kellens (jonaskellens) 2010-09-20 12:31:50

Hello.

What do you guys make from the backtrace ??


The strange thing is :

[macro-vakantie]
exten => s,1,MYSQL(Connect connid localhost dialplan asthost AsteriskHosted)

;exten => s,n,MYSQL(Query resultid ${connid} SELECT KNUMMER , vmcontext , accountcode_out , hostedformule , mohclass FROM AstDB where klantID=${ARG1})
; (1) THE ABOVE WORKS !!
exten => s,n,MYSQL(Query resultid ${connid} SELECT ast1 , ast2 , na , naID FROM vakantiedata where ID=${ARG1})
; (2) THE ABOVE FAILS !! What is the difference here ?!

exten => s,n,MYSQL(Fetch fetchid ${resultid} VAKAST1 VAKAST2 VAKNA VAKnaID)
exten => s,n,NoOp(vakantie-ast1 = ${VAKAST1} vakantie-ast2 = ${VAKAST2} na = ${VAKNA} naID = ${VAKnaID})
exten => s,n,MYSQL(Clear ${resultid})
exten => s,n,MYSQL(Disconnect ${connid})


This is the debug when using (1) :

[Sep 20 19:49:16] DEBUG[3424] pbx.c: Launching 'MYSQL'
[Sep 20 19:49:16] DEBUG[3424] app_addon_sql_mysql.c: MYSQL: data=Query resultid 1 SELECT KNUMMER , vmcontext , accountcode_out , hostedformule , mohclass FR
OM AstDB where klantID=59
[Sep 20 19:49:16] DEBUG[3424] app_addon_sql_mysql.c: MYSQL: setting var 'resultid' to value '2'
[Sep 20 19:49:16] DEBUG[3424] app_macro.c: Executed application: MYSQL
[Sep 20 19:49:16] DEBUG[3424] pbx.c: Launching 'MYSQL'
[Sep 20 19:49:16] DEBUG[3424] app_addon_sql_mysql.c: MYSQL: data=Fetch fetchid 2 VAKAST1 VAKAST2 VAKNA VAKnaID
[Sep 20 19:49:16] DEBUG[3424] app_addon_sql_mysql.c: ast_MYSQL_fetch: numFields=5
[Sep 20 19:49:16] DEBUG[3424] app_addon_sql_mysql.c: MYSQL: setting var 'fetchid' to value '1'
[Sep 20 19:49:16] DEBUG[3424] app_macro.c: Executed application: MYSQL


This the debug when using (2) :

[Sep 20 19:47:43] DEBUG[3366] pbx.c: Launching 'MYSQL'
[Sep 20 19:47:43] DEBUG[3366] app_addon_sql_mysql.c: MYSQL: data=Query resultid 1 SELECT ast1 , ast2 , na , naID FROM vakantiedata where ID=59
[Sep 20 19:47:47] DEBUG[3379] xmldoc.c: Cannot find variable 'SIPPEER' in tree 'description'
[Sep 20 19:47:47] DEBUG[3379] xmldoc.c: Cannot find variable 'SIPCHANINFO' in tree 'description'
[Sep 20 19:47:47] DEBUG[3379] xmldoc.c: Cannot find variable 'IAXPEER' in tree 'description'
[Sep 20 19:47:47] DEBUG[3379] xmldoc.c: Cannot find variable 'IAXVAR' in tree 'description'


By: Leif Madsen (lmadsen) 2010-09-28 10:39:17

This is probably a crash with the MYSQL() dialplan function somewhere. Looking at the backtrace I was thinking it had something to do with your GotoIfTime() inside the Macro(), but I'm not sure.

I know the MYSQL() application has caused me crashing problems in the past which were resolved by moving to func_odbc and res_odbc instead of using MYSQL().
By: Elazar Broad (ebroad) 2010-09-28 15:22:19

Please test the attached patch. Thanks!
By: Russell Bryant (russell) 2011-07-27 13:10:21.927-0500

Per the Asterisk maintenance timeline page at http://www.asterisk.org/asterisk-versions maintenance (bug) support for the 1.4 and 1.6.x branches has ended. For continued maintenance support please move to the 1.8 branch which is a long term support (LTS) branch. For more information about branch support, please see https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions

If this is still an issue, please open a new issue so it can be re-triaged appropriately. Thanks!