Summary:	ASTERISK-26263: SQL error when using realtime and registering extension / inserting into ps_contacts
Reporter:	Jeppe Ryskov Larsen (ryskov)	Labels:
Date Opened:	2016-08-03 03:05:46	Date Closed:	2016-10-04 12:58:55
Priority:	Major	Regression?	Yes
Status:	Closed/Complete	Components:	Resources/res_config_odbc
Versions:	13.10.0 13.11.0	Frequency of Occurrence	Constant
Related Issues:
Environment:	Ubuntu server	Attachments:	( 0) debug.log ( 1) jira_asterisk_26263_v13.patch
Description:	Hello. When upgrading from 13.9.1 to 13.10.0 or 13.11.0-rc1, we noticed an issue we havent seen before. We are using realtime with mysql. After the upgrade, when we tried registering a SIP phone (through WSS/WebRTC), we did not get any row inserted into ps_contacts. I turned on debugging in the CLI and noticed this: {code} INSERT INTO ps_contacts (id, qualify_timeout, reg_server, call_id, via_addr, outbound_proxy, expiration_time, path, endpoint, qualify_frequency, user_agent, authenticate_qualify, uri, via_port) VALUES (?, ?, ?, ?, ?, ?, ?, {code} The query it tries to execute gets cut off after in the value list, which caused the following error in the CLI {code} 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 {code} I can see in the CLI that all of the parameters were identified and set correctly: {code} [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = '10007-YRNU4HNN;@03e1e622887e8869da27281e003c3672' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 2 ('qualify_timeout') = '3.000000' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 3 ('reg_server') = 'odn1-voip-cluster02-asterisk03' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 4 ('call_id') = 'asqnfa0ebh0leu7nftrtd6' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 5 ('via_addr') = '192.0.2.245' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 6 ('outbound_proxy') = '' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 7 ('expiration_time') = '1470173873' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 8 ('path') = '' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 9 ('qualify_frequency') = '60' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 10 ('user_agent') = 'SIP.js/0.7.3' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 11 ('authenticate_qualify') = 'no' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 12 ('uri') = 'sip:dr0akpg6@[OMITTED]:56472;transport=WSS' [2016-08-02 23:27:53] DEBUG[3238]: res_config_odbc.c:129 custom_prepare: Parameter 13 ('via_port') = '0' {code} It seems really weird that the query would just get cut in half, but i tried putting the query together myself and executing it directly on the DB, and it gave me the exact same error, so i think this is what happens. If i finished the query manually and executed it, it inserted correctly.
Comments:	By: Asterisk Team (asteriskteam) 2016-08-03 03:05:46.901-0500 Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report. Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process]. By: Jeppe Ryskov Larsen (ryskov) 2016-08-03 03:07:07.725-0500 We have since downgraded back to 13.9.1 and everything works fine again, with no other changes. By: Andreas Krüger (woopstar) 2016-08-03 03:09:51.133-0500 Please also note, that while it worked to downgrade to 13.9.1 again, we did not downgrade the database, but left it with all updates from alembic, from Asterisk 13.11-rc1 By: Andreas Krüger (woopstar) 2016-08-03 03:28:57.165-0500 We also tried to create the query our self with the parameters shown in the description. The full query executes fine and inserts an entry into the database By: Rusty Newton (rnewton) 2016-08-03 14:13:24.666-0500 We require additional debug to continue with triage of your issue. Please follow the instructions on the wiki [1] for how to collect debugging information from Asterisk. For expediency, where possible, attach the debug with a '.txt' file extension so that the debug will be usable for further analysis. Thanks! [1] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information By: Rusty Newton (rnewton) 2016-08-03 14:15:59.809-0500 Very odd! Please attach a debug log as described in the above comment so we can see anything else useful in the debug. At least a few hundred lines before and after the INSERT.   Make sure to include warning,error,notice,verbose,debug with verbose set to 5 or above and debug set to 5 or above. Include the "pjsip set logger on" output within the debug log as well. Thanks! By: Jeppe Ryskov Larsen (ryskov) 2016-08-04 04:56:08.978-0500 When we get the time we will upgrade one of our machines to 13.10 and reproduce the issue with proper debug information. Tomorrow or sometime early next week. By: Asterisk Team (asteriskteam) 2016-08-18 12:00:01.838-0500 Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1]. [1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines By: Jeppe Ryskov Larsen (ryskov) 2016-08-22 08:05:11.957-0500 I have attached debug output. It container verbose,debug,error,warning,notice and SIP trace. It seems everything goes okay but the insert into ps_contacts By: Asterisk Team (asteriskteam) 2016-08-22 08:10:36.669-0500 This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable. By: Jeppe Ryskov Larsen (ryskov) 2016-08-22 08:15:58.097-0500 Just noticed it happens if the query exceed 255 characters. Seems like not enough is allocated for the string. It happens because we have generic generated views, which are named something like 'ps_contacts_[somemd5sum]', which we configure in extconfig.conf . Interesting. By: Andreas Krüger (woopstar) 2016-08-22 12:46:46.729-0500 I agree with Jeppe. Problem is the variable holding the query used in the prepared statement. It's only allocating 255 chars, but as our table name is a bit long as it's server dependent, this query length exceeds the allocated variable. Solution is to allocate more than 255 chars for the query. This bug has been introduced in 13.10 and newer versions, while it works fine in 13.9 and lower. Must be a result of the new res_odbc that has been written? By: Richard Mudgett (rmudgett) 2016-09-12 14:14:06.220-0500 The buffer overflow is not the result of the res_odbc work.  From v13.9.1 to v13.10.0 these columns were added to the ps_contacts table: via_addr, via_port, call_id, reg_server, and authenticate_qualify.  These new columns add 63 characters to the query and thus overfilled the buffer you mention.  I'm working on a fix to eliminate the fixed buffer sizes to avoid the problem in the future for this and other tables. By: Richard Mudgett (rmudgett) 2016-09-13 12:42:36.571-0500 [^jira_asterisk_26263_v13.patch] - This patch changes the fixed size SQL request buffer to a dynamically sized buffer associated with the thread.  Now the generated SQL query will always fit in the buffer. I don't have a setup to actually test this patch.  Please test and report back. Apply patch at the root Asterisk source directory: {{patch -p1 -i jira_asterisk_26263_v13.patch}} By: Andreas Krüger (woopstar) 2016-09-14 02:55:11.267-0500 Hi Richard, Jeppe and I will test this within a few days and see if the applied patch works.