[Home]

Summary:ASTERISK-15881: [patch] Asterisk Crashes With Core Dump When FUNC_ODBC Processes SQL Statements With Errors
Reporter:David Elliott (david elliott)Labels:
Date Opened:2010-03-26 09:23:28Date Closed:2010-05-27 10:20:31
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Functions/func_odbc
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 20100326__issue17101.diff.txt
( 1) valgrind.txt
Description:When func_odbc /res_odbc processes SQL with table name, column name or variables missing it generates a segmentation violation and subsequent core dump.  

This latest set of issues were generated by Asterisk 1.6.2.6 running on a fully upgraded Centos 5.4 (2.6.18-164.15.1.el5 #1 SMP).  The same issue occurs across a range of Asterisk versions and Linux distributions.  I am pretty sure the issue is caused by the way ODBC driver errors are handled by func_odbc / res_odbc.  

The res_odbc / func_odbc reports a syntax error to the console which is ignored.  Instead of re-acting to the valid ODBC error,   func_odbc / res_odbc does a DISCONNECT / CONNECT followed by a re-execution of the same faulty SQL statement.  The software has assumed that the original error was caused by a connection time out and seeks to fix the problem by disconnecting and re-connecting to the database.  Needless to say quite simple, SQL syntax error will stop Asterisk in its tracks.





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

MYSQL TABLE

CREATE TABLE `tbl_hangup_handler` (
 `hup_rowid` int(10) unsigned NOT NULL auto_increment,
 `hup_node` varchar(20) default NULL,
 `hup_service` varchar(80) default NULL,
 `hup_uniqueid` varchar(20) default NULL,
 PRIMARY KEY  (`hup_rowid`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

The DSN was working fine.  Func_odbc works fine so long as there are no syntax errors.  

FUNC_ODBC.CONF

; deleiberately tries to access a non-existent table
[DELETE_BADTABLE]
prefix=FO
dsn=astsys
writesql=DELETE FROM astsys.tbl_core_dump

; deliberately includes a non-existent column name
[DELETE_BADCOLUMN]
prefix=FO
dsn=astsys
writesql=DELETE FROM astsys.tbl_hangup_handler WHERE hup_bad_rowid = ${ARG1}

; working
[DELETE]
prefix=FO
dsn=astsys
writesql=DELETE FROM astsys.tbl_hangup_handler WHERE hup_rowid = ${ARG1}

EXTENSIONS.CONF

Any of the FO_DELETE, FO_DELETE_BADTABLE, DELETE_BADCOLUMN functions will lead to a similar outcome.  Anything like a bad table name, a bad colum name or simply a missing value will cause a segmentation violation leading to Asterisk exiting with a core dump.   This trace was generated using FO_DELETE with a missing value.  

[func-odbc-test]
exten => s,1,NoOp(Dial through Conference Test)
exten => s,n,Answer()
exten => s,n,Wait(2)
; Bad table name
;exten => s,n,Set(FO_DELETE_BADTABLE(1234));
; Bad column name
;exten => s,n,Set(FO_DELETE_BADCOLUMN(1234));
; Value omitted
exten => s,n,Set(FO_DELETE());
exten => s,n,Hangup()

CONSOLE OUTPUT

   -- Executing [s@func-odbc-test:1] NoOp("SIP/8018-00000000", "Dial through Conference Test") in new stack
   -- Executing [s@func-odbc-test:2] Answer("SIP/8018-00000000", "") in new stack
   -- Executing [s@func-odbc-test:3] Wait("SIP/8018-00000000", "2") in new stack
   -- Executing [s@func-odbc-test:4] Set("SIP/8018-00000000", "FO_DELETE()") in new stack
[Mar 26 13:57:43] WARNING[24809]: func_odbc.c:183 generic_execute: SQL Execute returned an error -1: 42000: [MySQL][ODBC 3.51 Driver][mysqld-5.0.77]You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1 (186)
[Mar 26 13:57:43] WARNING[24809]: func_odbc.c:191 generic_execute: SQL Exec Direct failed (-1)![DELETE FROM astsys.tbl_hangup_handler WHERE hup_rowid = ]
[Mar 26 13:57:43] WARNING[24809]: res_odbc.c:583 ast_odbc_direct_execute: SQL Exec Direct failed.  Attempting a reconnect...
[Mar 26 13:57:43] NOTICE[24809]: res_odbc.c:1427 odbc_obj_connect: Connecting astsys
[Mar 26 13:57:43] NOTICE[24809]: res_odbc.c:1455 odbc_obj_connect: res_odbc: Connected to astsys [astsys]
[Mar 26 13:57:43] WARNING[24809]: func_odbc.c:183 generic_execute: SQL Execute returned an error -1: 42000: [MySQL][ODBC 3.51 Driver][mysqld-5.0.77]You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1 (186)
[Mar 26 13:57:43] WARNING[24809]: func_odbc.c:191 generic_execute: SQL Exec Direct failed (-1)![DELETE FROM astsys.tbl_hangup_handler WHERE hup_rowid = ]
[Mar 26 13:57:43] WARNING[24809]: res_odbc.c:583 ast_odbc_direct_execute: SQL Exec Direct failed.  Attempting a reconnect...
[Mar 26 13:57:43] NOTICE[24809]: res_odbc.c:1427 odbc_obj_connect: Connecting astsys
[Mar 26 13:57:43] NOTICE[24809]: res_odbc.c:1455 odbc_obj_connect: res_odbc: Connected to astsys [astsys]
*** glibc detected *** asterisk: double free or corruption (!prev): 0x09173170 ***
[Mar 26 13:57:43] ERROR[24809]: astobj2.c:279 __ao2_ref: refcount -1 on object 0x9173198
[Mar 26 13:57:43] ERROR[24809]: astobj2.c:110 INTERNAL_OBJ: user_data is NULL
Comments:By: Tilghman Lesher (tilghman) 2010-03-26 10:00:28

Please run this under valgrind, as detailed in doc/valgrind.txt.
By: David Elliott (david elliott) 2010-03-26 10:47:44

I had to leave out the --suppressions section because valgrind did not like the valgrind.supp file.
By: David Elliott (david elliott) 2010-03-26 10:55:17

Slightly more informative output from Asterisk

   -- Executing [s@func-odbc-test:1] NoOp("SIP/8018-00000000", "Dial through Conference Test") in new stack
   -- Executing [s@func-odbc-test:2] Answer("SIP/8018-00000000", "") in new stack
   -- Executing [s@func-odbc-test:3] Wait("SIP/8018-00000000", "2") in new stack
   -- Executing [s@func-odbc-test:4] Set("SIP/8018-00000000", "FO_DELETE()") in new stack
[Mar 26 15:54:22] WARNING[30953]: func_odbc.c:183 generic_execute: SQL Execute returned an error -1: 42000: [MySQL][ODBC 3.51 Driver][mysqld-5.0.77]You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1 (186)
[Mar 26 15:54:22] WARNING[30953]: func_odbc.c:191 generic_execute: SQL Exec Direct failed (-1)![DELETE FROM astsys.tbl_hangup_handler WHERE hup_rowid = ]
[Mar 26 15:54:22] WARNING[30953]: res_odbc.c:583 ast_odbc_direct_execute: SQL Exec Direct failed.  Attempting a reconnect...
[Mar 26 15:54:22] NOTICE[30953]: res_odbc.c:1427 odbc_obj_connect: Connecting astsys
[Mar 26 15:54:22] NOTICE[30953]: res_odbc.c:1455 odbc_obj_connect: res_odbc: Connected to astsys [astsys]
[Mar 26 15:54:22] WARNING[30953]: func_odbc.c:183 generic_execute: SQL Execute returned an error -1: 42000: [MySQL][ODBC 3.51 Driver][mysqld-5.0.77]You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1 (186)
[Mar 26 15:54:22] WARNING[30953]: func_odbc.c:191 generic_execute: SQL Exec Direct failed (-1)![DELETE FROM astsys.tbl_hangup_handler WHERE hup_rowid = ]
[Mar 26 15:54:22] WARNING[30953]: res_odbc.c:583 ast_odbc_direct_execute: SQL Exec Direct failed.  Attempting a reconnect...
[Mar 26 15:54:22] NOTICE[30953]: res_odbc.c:1427 odbc_obj_connect: Connecting astsys
[Mar 26 15:54:22] NOTICE[30953]: res_odbc.c:1455 odbc_obj_connect: res_odbc: Connected to astsys [astsys]
[Mar 26 15:54:22] ERROR[30953]: astobj2.c:279 __ao2_ref: refcount -1 on object 0x4047490
[Mar 26 15:54:22] ERROR[30953]: astobj2.c:110 INTERNAL_OBJ: user_data is NULL
WARNING: Freeing unused memory at 0x4047468, in __ao2_ref of astobj2.c, line 295
[Mar 26 15:54:22] ERROR[30953]: astobj2.c:279 __ao2_ref: refcount -2 on object 0x4047490
[Mar 26 15:54:22] ERROR[30953]: astobj2.c:110 INTERNAL_OBJ: user_data is NULL
WARNING: Freeing unused memory at 0x4047468, in __ao2_ref of astobj2.c, line 295
WARNING: Freeing unused memory at 0x4047468, in __ao2_ref of astobj2.c, line 295
[Mar 26 15:54:22] ERROR[30953]: astobj2.c:279 __ao2_ref: refcount -3 on object 0x4047490
[Mar 26 15:54:22] ERROR[30953]: astobj2.c:110 INTERNAL_OBJ: user_data is NULL
WARNING: Freeing unused memory at 0x4047468, in __ao2_ref of astobj2.c, line 295
[Mar 26 15:54:22] ERROR[30953]: astobj2.c:279 __ao2_ref: refcount -4 on object 0x4047490
[Mar 26 15:54:22] ERROR[30953]: astobj2.c:110 INTERNAL_OBJ: user_data is NULL
   -- Executing [s@func-odbc-test:5] Hangup("SIP/8018-00000000", "") in new stack
 == Spawn extension (func-odbc-test, s, 5) exited non-zero on 'SIP/8018-00000000'
By: Tilghman Lesher (tilghman) 2010-03-26 11:23:42

What's pretty clear from the valgrind is that the objects are not properly refcounted.  This is what is causing the crash.  The disconnect/reconnect loop is a red herring.
By: David Elliott (david elliott) 2010-03-26 11:46:26

The patched version also generates a segmentation violation and exits with a core dump.


   -- Executing [s@func-odbc-test:1] NoOp("SIP/8018-00000000", "Dial through Conference Test") in new stack
   -- Executing [s@func-odbc-test:2] Answer("SIP/8018-00000000", "") in new stack
   -- Executing [s@func-odbc-test:3] Wait("SIP/8018-00000000", "2") in new stack
   -- Executing [s@func-odbc-test:4] Set("SIP/8018-00000000", "FO_DELETE()") in new stack
[Mar 26 16:45:36] WARNING[450]: func_odbc.c:183 generic_execute: SQL Execute returned an error -1: 42000: [MySQL][ODBC 3.51 Driver][mysqld-5.0.77]You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1 (186)
[Mar 26 16:45:36] WARNING[450]: func_odbc.c:191 generic_execute: SQL Exec Direct failed (-1)![DELETE FROM astsys.tbl_hangup_handler WHERE hup_rowid = ]
[Mar 26 16:45:36] WARNING[450]: res_odbc.c:583 ast_odbc_direct_execute: SQL Exec Direct failed.  Attempting a reconnect...
[Mar 26 16:45:36] NOTICE[450]: res_odbc.c:1428 odbc_obj_connect: Connecting astsys
[Mar 26 16:45:36] NOTICE[450]: res_odbc.c:1456 odbc_obj_connect: res_odbc: Connected to astsys [astsys]
[Mar 26 16:45:36] WARNING[450]: func_odbc.c:183 generic_execute: SQL Execute returned an error -1: 42000: [MySQL][ODBC 3.51 Driver][mysqld-5.0.77]You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1 (186)
[Mar 26 16:45:36] WARNING[450]: func_odbc.c:191 generic_execute: SQL Exec Direct failed (-1)![DELETE FROM astsys.tbl_hangup_handler WHERE hup_rowid = ]
[Mar 26 16:45:36] WARNING[450]: res_odbc.c:583 ast_odbc_direct_execute: SQL Exec Direct failed.  Attempting a reconnect...
[Mar 26 16:45:36] NOTICE[450]: res_odbc.c:1428 odbc_obj_connect: Connecting astsys
[Mar 26 16:45:36] NOTICE[450]: res_odbc.c:1456 odbc_obj_connect: res_odbc: Connected to astsys [astsys]
[Mar 26 16:45:36] ERROR[450]: astobj2.c:279 __ao2_ref: refcount -1 on object 0x9068be0
[Mar 26 16:45:36] ERROR[450]: astobj2.c:110 INTERNAL_OBJ: user_data is NULL
WARNING: Freeing unused memory at 0x9068bb8, in __ao2_ref of astobj2.c, line 295
[Mar 26 16:45:36] ERROR[450]: astobj2.c:279 __ao2_ref: refcount -2 on object 0x9068be0
[Mar 26 16:45:36] ERROR[450]: astobj2.c:110 INTERNAL_OBJ: user_data is NULL
WARNING: Freeing unused memory at 0x9068bb8, in __ao2_ref of astobj2.c, line 295
[Mar 26 16:45:36] ERROR[450]: astobj2.c:279 __ao2_ref: refcount -3 on object 0x9068be0
[Mar 26 16:45:36] ERROR[450]: astobj2.c:110 INTERNAL_OBJ: user_data is NULL
WARNING: Freeing unused memory at 0x9068bb8, in __ao2_ref of astobj2.c, line 295
[Mar 26 16:45:36] ERROR[450]: astobj2.c:279 __ao2_ref: refcount -4 on object 0x9068be0
[Mar 26 16:45:36] ERROR[450]: astobj2.c:110 INTERNAL_OBJ: user_data is NULL
WARNING: Freeing unused memory at 0x9068bb8, in __ao2_ref of astobj2.c, line 295
   -- Executing [s@func-odbc-test:5] Hangup("SIP/8018-00000000", "") in new stack
 == Spawn extension (func-odbc-test, s, 5) exited non-zero on 'SIP/8018-00000000'
By: David Elliott (david elliott) 2010-03-30 04:25:28

Has there been any progress on this one?
By: Tilghman Lesher (tilghman) 2010-03-30 10:07:55

No, there has not.  The issue is in our queue, and it will be worked upon as resources permit.  Please be patient; your issue may not get addressed immediately.
By: David Elliott (david elliott) 2010-04-27 03:59:15

Do you have any idea when resources will be available to look at this issue?
By: Paul Belanger (pabelanger) 2010-04-27 08:55:34

At this point, no.  It is in the queue and will be looked at when developer resources become available.
By: Tilghman Lesher (tilghman) 2010-04-27 10:02:12

See patch in related issue.
By: Tilghman Lesher (tilghman) 2010-05-26 22:33:56

David Elliott:  have you been able to reproduce this issue in the 1.6.2 branch since the related issue was committed?
By: David Elliott (david elliott) 2010-05-27 04:43:59

I have applied the patch to all of my Asterisk machines.   I am still running Asterisk 1.6.2.6 + Patch from the linked issue 0017245.  This patch seem to have resolved the issue.

I will move up to the next subversion from the main branch sometime soon.  I will confirm this is OK when I upgrade to something higher than 1.6.2.6.

Many thanks