Hello everyone,
I am having an issue with Asterisk and ODBC. I am using Asterisk/ODBC to fetch names and phone numbers out of a MySQL database, and allowing the user to be transferred to the person of their choice. However, I am running into some issues with connecting to the database.
Most of the time, ODBC will connect flawlessly to the MySQL server with no hanging or hiccups at all. However, after around 40 minutes to an hour of inactivity, Asterisk will hang completely when trying to connect to the database. It will not process any requests for around 15 or 16 minutes while it waits to hear something from ODBC. Now the caller isn’t going to wait that long and will hang up, which causes other issues because Asterisk does not recognize the user hanging up during this 15-16 minute hang. However, if you wait on the line during these 15-16 minutes, asterisk will reconnect and everything will happen normally.
One more interesting piece of information is if I am using the MySQL CLI on the same machine asterisk is on, and I leave that idle for the same period, the query will hang and I am forced to CTRL+C out. I am not sure if this indicates something on the SQL server side, or not.
I am running out of ideas. I have been making changes to my ODBC ini file to to try and add in idle checks to try and ease some connection timeout problems, but nothing has worked. Here is all of my information:
Asterisk Version: 1.8.20.0 on CentOS (Installed via YUM, not by me)
unixODBC version : 2.2.14
/etc/odbc.ini :
[quote=“/etc/odbc.ini”][eivr]
Description = MySQLconnection for asterisk eivr
Driver = MySQL
Database = DATABASE
Server = SERVER
User = USERNAME
Password = PASSWORD
Port = PORT
option = 4194304
readtimeout = 15
[/quote]
/etc/asterisk/res_odbc.conf :
[quote=“/etc/asterisk/res_odbc.conf”][eivr]
enabled => yes
dsn => eivr
username => USERNAME
password => PASSWORD
pre-connect => no
idlecheck => 300
connect_timeout =>5
negative_connection_cache => 10
sanitysql => select 1
[/quote]
ODBC Trace File:
ODBC][11264][1362522195.493363][SQLAllocHandle.c][529]
Entry:
Handle Type = 3
Input Handle = 0xb760f890
[ODBC][11264][1362522195.495500][SQLAllocHandle.c][1064]
Exit:[SQL_SUCCESS]
Output Handle = 0xb746c9b0
[ODBC][11264][1362522195.495848][SQLPrepare.c][192]
Entry:
Statement = 0xb746c9b0
SQL = [select 1][length = 8 (SQL_NTS)]
[ODBC][11264][1362522195.496333][SQLPrepare.c][367]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362522195.496527][SQLExecute.c][183]
Entry:
Statement = 0xb746c9b0
[ODBC][11264][1362522201.274362][SQLSetConnectAttr.c][321]
Entry:
Connection = 0xb760f890
Attribute = SQL_ATTR_AUTOCOMMIT
Value = 0x1
StrLen = 0
<HANGS FOR 15+ MINUTES HERE>
[ODBC][11264][1362523121.121580][SQLExecute.c][344]
Exit:[SQL_ERROR]
DIAG [08S01] [MySQL][ODBC 5.1 Driver][mysqld-5.1.49-community-log]Lost connection to MySQL server during query
[ODBC][11264][1362523121.122480][SQLFreeHandle.c][378]
Entry:
Handle Type = 3
Input Handle = 0xb746c9b0
[ODBC][11264][1362523121.122622][SQLSetConnectAttr.c][675]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.123075][SQLSetConnectAttr.c][321]
Entry:
Connection = 0xb760f890
Attribute = SQL_ATTR_TXN_ISOLATION
Value = 0x2
StrLen = 0
[ODBC][11264][1362523121.123345][SQLSetConnectAttr.c][675]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.123344][SQLFreeHandle.c][480]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.123803][SQLDisconnect.c][204]
Entry:
Connection = 0xb760f890
[ODBC][11264][1362523121.124200][SQLAllocHandle.c][364]
Entry:
Handle Type = 2
Input Handle = 0xb74368e0
[ODBC][11264][1362523121.124534][SQLAllocHandle.c][482]
Exit:[SQL_SUCCESS]
Output Handle = 0xb760d898
[ODBC][11264][1362523121.124757][SQLSetConnectAttr.c][321]
Entry:
Connection = 0xb760d898
Attribute = SQL_ATTR_LOGIN_TIMEOUT
Value = 0x5
StrLen = 0
[ODBC][11264][1362523121.125017][SQLDisconnect.c][341]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.125279][SQLSetConnectAttr.c][504]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.125395][SQLFreeHandle.c][279]
Entry:
Handle Type = 2
Input Handle = 0xb760f890
[ODBC][11264][1362523121.125754][SQLSetConnectAttr.c][321]
Entry:
Connection = 0xb760d898
Attribute = SQL_ATTR_CONNECTION_TIMEOUT
Value = 0x5
StrLen = 0
[ODBC][11264][1362523121.125847][SQLFreeHandle.c][330]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.126346][SQLAllocHandle.c][364]
Entry:
Handle Type = 2
Input Handle = 0xb74368e0
[ODBC][11264][1362523121.126649][SQLAllocHandle.c][482]
Exit:[SQL_SUCCESS]
Output Handle = 0xb74dae28
[ODBC][11264][1362523121.126966][SQLSetConnectAttr.c][321]
Entry:
Connection = 0xb74dae28
Attribute = SQL_ATTR_LOGIN_TIMEOUT
Value = 0x5
StrLen = 0
[ODBC][11264][1362523121.127062][SQLSetConnectAttr.c][504]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.127419][SQLConnect.c][3614]
Entry:
Connection = 0xb760d898
Server Name = [eivr][length = 4 (SQL_NTS)]
User Name = [eivr2][length = 5 (SQL_NTS)]
Authentication = [**************][length = 14 (SQL_NTS)]
[ODBC][11264][1362523121.127367][SQLSetConnectAttr.c][504]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.128691][SQLSetConnectAttr.c][321]
Entry:
Connection = 0xb74dae28
Attribute = SQL_ATTR_CONNECTION_TIMEOUT
Value = 0x5
StrLen = 0
UNICODE Using encoding ASCII ‘ISO8859-1’ and UNICODE ‘UCS-2LE’
[ODBC][11264][1362523121.151446][SQLConnect.c][4188]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.151563][SQLSetConnectAttr.c][504]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.152344][SQLAllocHandle.c][529]
Entry:
Handle Type = 3
Input Handle = 0xb760d898
[ODBC][11264][1362523121.152434][SQLConnect.c][3614]
Entry:
Connection = 0xb74dae28
Server Name = [eivr][length = 4 (SQL_NTS)]
User Name = [eivr2][length = 5 (SQL_NTS)]
Authentication = [**************][length = 14 (SQL_NTS)]
[ODBC][11264][1362523121.152839][SQLAllocHandle.c][1064]
Exit:[SQL_SUCCESS]
Output Handle = 0xb7607e78
[ODBC][11264][1362523121.153089][SQLExecDirect.c][236]
Entry:
Statement = 0xb7607e78
SQL = [SELECT number FROM people WHERE (ivr LIKE ‘226277%’ AND number LIKE ‘(831) 582-%’) ORDER BY lastname][length = 100 (SQL_NTS)]
UNICODE Using encoding ASCII ‘ISO8859-1’ and UNICODE ‘UCS-2LE’
[ODBC][11264][1362523121.171231][SQLConnect.c][4188]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.172196][SQLAllocHandle.c][529]
Entry:
Handle Type = 3
Input Handle = 0xb74dae28
[ODBC][11264][1362523121.172539][SQLAllocHandle.c][1064]
Exit:[SQL_SUCCESS]
Output Handle = 0xb746c9b0
[ODBC][11264][1362523121.172879][SQLPrepare.c][192]
Entry:
Statement = 0xb746c9b0
SQL = [select 1][length = 8 (SQL_NTS)]
[ODBC][11264][1362523121.173074][SQLPrepare.c][367]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.173252][SQLExecute.c][183]
Entry:
Statement = 0xb746c9b0
[ODBC][11264][1362523121.173940][SQLExecDirect.c][499]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.174170][SQLNumResultCols.c][152]
Entry:
Statement = 0xb7607e78
Column Count = 0xb6721b0e
[ODBC][11264][1362523121.174333][SQLNumResultCols.c][244]
Exit:[SQL_SUCCESS]
Count = 0xb6721b0e → 1
[ODBC][11264][1362523121.174518][SQLFetch.c][158]
Entry:
Statement = 0xb7607e78
[ODBC][11264][1362523121.174771][SQLExecute.c][344]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.174812][SQLFetch.c][340]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.175155][SQLDescribeCol.c][243]
Entry:
Statement = 0xb7607e78
Column Number = 1
Column Name = 0xb6721b11
Buffer Length = 256
Name Length = 0xb6721b0c
Data Type = (nil)
Column Size = 0xb6721af8
Decimal Digits = (nil)
Nullable = (nil)
[ODBC][11264][1362523121.175114][SQLFreeHandle.c][378]
Entry:
Handle Type = 3
Input Handle = 0xb746c9b0
[ODBC][11264][1362523121.175533][SQLDescribeCol.c][493]
Exit:[SQL_SUCCESS]
Column Name = [number]
Data Type = NULLPTR
Column Size = 0xb6721af8 → 250
Decimal Digits = NULLPTR
Nullable = NULLPTR
[ODBC][11264][1362523121.175809][SQLGetData.c][233]
Entry:
Statement = 0xb7607e78
Column Number = 1
Target Type = 1 SQL_CHAR
Buffer Length = 251
Target Value = 0xb763da54
StrLen Or Ind = 0xb6721b04
[ODBC][11264][1362523121.175954][SQLFreeHandle.c][480]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.176254][SQLGetData.c][497]
Exit:[SQL_SUCCESS]
Buffer = [(831) 582-3364]
Strlen Or Ind = 0xb6721b04 → 14
[ODBC][11264][1362523121.176447][SQLFetch.c][158]
Entry:
Statement = 0xb7607e78
[ODBC][11264][1362523121.176630][SQLFetch.c][340]
Exit:[SQL_NO_DATA]
[ODBC][11264][1362523121.176946][SQLCloseCursor.c][135]
Entry:
Statement = 0xb7607e78
[ODBC][11264][1362523121.177132][SQLCloseCursor.c][227]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.177309][SQLFreeHandle.c][378]
Entry:
Handle Type = 3
Input Handle = 0xb7607e78
[ODBC][11264][1362523121.177516][SQLFreeHandle.c][480]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.179467][SQLSetConnectAttr.c][321]
Entry:
Connection = 0xb74dae28
Attribute = SQL_ATTR_AUTOCOMMIT
Value = 0x1
StrLen = 0
[ODBC][11264][1362523121.179685][SQLSetConnectAttr.c][675]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.179940][SQLSetConnectAttr.c][321]
Entry:
Connection = 0xb74dae28
Attribute = SQL_ATTR_TXN_ISOLATION
Value = 0x2
StrLen = 0
[ODBC][11264][1362523121.181606][SQLSetConnectAttr.c][675]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.181991][SQLAllocHandle.c][529]
Entry:
Handle Type = 3
Input Handle = 0xb74dae28
[ODBC][11264][1362523121.182218][SQLAllocHandle.c][1064]
Exit:[SQL_SUCCESS]
Output Handle = 0xb7607e78
[ODBC][11264][1362523121.182418][SQLExecDirect.c][236]
Entry:
Statement = 0xb7607e78
SQL = [SELECT firstname,lastname FROM people WHERE (ivr LIKE ‘226277%’ AND number LIKE ‘(831) 582-%’) ORDER BY lastname][length = 112 (SQL_NTS)]
[ODBC][11264][1362523121.185139][SQLExecDirect.c][499]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.185413][SQLNumResultCols.c][152]
Entry:
Statement = 0xb7607e78
Column Count = 0xb6721b0e
[ODBC][11264][1362523121.185578][SQLNumResultCols.c][244]
Exit:[SQL_SUCCESS]
Count = 0xb6721b0e → 2
[ODBC][11264][1362523121.185827][SQLFetch.c][158]
Entry:
Statement = 0xb7607e78
[ODBC][11264][1362523121.186024][SQLFetch.c][340]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.186181][SQLDescribeCol.c][243]
Entry:
Statement = 0xb7607e78
Column Number = 1
Column Name = 0xb6721b11
Buffer Length = 256
Name Length = 0xb6721b0c
Data Type = (nil)
Column Size = 0xb6721af8
Decimal Digits = (nil)
Nullable = (nil)
[ODBC][11264][1362523121.186376][SQLDescribeCol.c][493]
Exit:[SQL_SUCCESS]
Column Name = [firstname]
Data Type = NULLPTR
Column Size = 0xb6721af8 → 250
Decimal Digits = NULLPTR
Nullable = NULLPTR
[ODBC][11264][1362523121.187194][SQLGetData.c][233]
Entry:
Statement = 0xb7607e78
Column Number = 1
Target Type = 1 SQL_CHAR
Buffer Length = 251
Target Value = 0xb763da54
StrLen Or Ind = 0xb6721b04
[ODBC][11264][1362523121.187402][SQLGetData.c][497]
Exit:[SQL_SUCCESS]
Buffer = [William]
Strlen Or Ind = 0xb6721b04 → 7
[ODBC][11264][1362523121.187912][SQLDescribeCol.c][243]
Entry:
Statement = 0xb7607e78
Column Number = 2
Column Name = 0xb6721b11
Buffer Length = 256
Name Length = 0xb6721b0c
Data Type = (nil)
Column Size = 0xb6721af8
Decimal Digits = (nil)
Nullable = (nil)
[ODBC][11264][1362523121.188092][SQLDescribeCol.c][493]
Exit:[SQL_SUCCESS]
Column Name = [lastname]
Data Type = NULLPTR
Column Size = 0xb6721af8 → 250
Decimal Digits = NULLPTR
Nullable = NULLPTR
[ODBC][11264][1362523121.188255][SQLGetData.c][233]
Entry:
Statement = 0xb7607e78
Column Number = 2
Target Type = 1 SQL_CHAR
Buffer Length = 251
Target Value = 0xb763da54
StrLen Or Ind = 0xb6721b04
[ODBC][11264][1362523121.188445][SQLGetData.c][497]
Exit:[SQL_SUCCESS]
Buffer = [Camarra]
Strlen Or Ind = 0xb6721b04 → 7
[ODBC][11264][1362523121.189214][SQLFetch.c][158]
Entry:
Statement = 0xb7607e78
[ODBC][11264][1362523121.189409][SQLFetch.c][340]
Exit:[SQL_NO_DATA]
[ODBC][11264][1362523121.189939][SQLCloseCursor.c][135]
Entry:
Statement = 0xb7607e78
[ODBC][11264][1362523121.190098][SQLCloseCursor.c][227]
Exit:[SQL_SUCCESS]
[ODBC][11264][1362523121.190279][SQLFreeHandle.c][378]
Entry:
Handle Type = 3
Input Handle = 0xb7607e78
[ODBC][11264][1362523121.191058][SQLFreeHandle.c][480]
Exit:[SQL_SUCCESS]
Asterisk CLI Errors :
[quote=“Asterisk CLI”][Mar 4 16:22:19] DEBUG[1569]: pbx.c:4470 pbx_extension_helper: Launching ‘GotoIf’
– Executing [1@Avaya-vm:2] GotoIf(“SIP/Avaya-vm-00000012”, “0?error,5,1”) in new stack
[Mar 4 16:22:19] DEBUG[1569]: pbx.c:10423 pbx_builtin_gotoif: Not taking any branch
[Mar 4 16:22:19] DEBUG[1569]: pbx.c:3479 ast_str_retrieve_variable: Result of ‘myVar’ is ‘226277’
[Mar 4 16:22:19] DEBUG[1569]: pbx.c:4065 ast_str_substitute_variables_full: Evaluating ‘ARG1’ (from ‘ARG1}%’ AND number LIKE ‘(XXX) XXX-%’) ORDER BY lastname’ len 4)
[Mar 4 16:22:19] DEBUG[1569]: pbx.c:3479 ast_str_retrieve_variable: Result of ‘ARG1’ is ‘226277’
[Mar 4 16:22:19] DEBUG[27008]: res_rtp_asterisk.c:1547 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Mar 4 16:22:19] DEBUG[27008]: res_rtp_asterisk.c:1547 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Mar 4 16:22:19] DEBUG[27008]: res_rtp_asterisk.c:1547 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Mar 4 16:22:19] DEBUG[27008]: res_rtp_asterisk.c:1547 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Mar 4 16:22:19] DEBUG[27008]: res_rtp_asterisk.c:1547 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Mar 4 16:22:19] DEBUG[27008]: res_rtp_asterisk.c:1547 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Mar 4 16:22:19] DEBUG[27008]: res_rtp_asterisk.c:1547 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Mar 4 16:22:19] DEBUG[27008]: res_rtp_asterisk.c:1547 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Mar 4 16:22:19] DEBUG[27008]: res_rtp_asterisk.c:1547 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4)
[Mar 4 16:22:21] DEBUG[27008]: res_rtp_asterisk.c:1807 ast_rtcp_read: Got RTCP report of 104 bytes
[Mar 4 16:22:26] DEBUG[27008]: res_rtp_asterisk.c:1807 ast_rtcp_read: Got RTCP report of 80 bytes
… …
[Mar 4 16:37:45] WARNING[1569]: res_odbc.c:1406 _ast_odbc_request_obj2: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 Driver]Lost connection to MySQL server during query
[Mar 4 16:37:45] DEBUG[1569]: res_odbc.c:1497 odbc_obj_disconnect: Disconnected 0 from eivr [eivr]
[Mar 4 16:37:45] DEBUG[1569]: res_odbc.c:1504 odbc_obj_disconnect: Database handle 0xb7415c40 deallocated
[Mar 4 16:37:45] NOTICE[1569]: res_odbc.c:1528 odbc_obj_connect: Re-connecting eivr
[Mar 4 16:37:45] NOTICE[1569]: res_odbc.c:1563 odbc_obj_connect: res_odbc: Connected to eivr [eivr]
[/quote]
NOTE: I sometimes get an HY010 error instead
Thanks for your time, I appreciate any assistance.