[asterisk-users] Spontaneous reboot due to MySQL lookups ? (Jonas Kellens)
Stefan Viljoen
viljoens at verishare.co.za
Fri Oct 5 01:12:45 CDT 2018
Hi Jonas
We have more or less this behaviour with 1.8.32.3 when writing CDRs to ODBC on Percona 5.6 (MySQL drop-in replacement with some optimisations and extra features.)
In our case the system does NOT reboot, but Asterisk itself crashes with a segfault inside unixODBC itself.
We're running on Centos 7, so the first thing we tried was to upgrade the ODBC drivers to the most recent version, and also use the most recent MySQL ODBC connector.
This did not solve the problem, and the spontaneous shutdowns (and then restarts via Centos 7 systemd) of the 1.8.32.3 instances continued.
Eventually we traced this to contention on the CDR table itself in the associated MySQL / Percona instance. We had a stored procedure running on the CDR table at set intervals via a MySQL timed event that was converting the Asterisk CDR data into another table we use for our own purposes. This was effectively locking the CDR table in ways that wasn't allowing Asterisk 1.8.32.3 to enter CDRs when it wanted to.
The practical effect in real-world terms was that people could make a call, but then NOT do another call on that same extension, for up to five or ten minutes at a time. This was because the Asterisk 1.8.32.3 instance was waiting to get access to the CDR table to write that extensions most-recent CDR record in, and was holding onto the extension to prevent a new call when it hadn't yet managed to write into the CDR table for the previous call.
Also, if pushed hard enough with concurrent calls, the Asterisk instance would get segfaulted due to a segfault in the ODBC drivers, due to this contention and waiting for access to the CDR table.
All I can recommend is to upgrade to, for example, Asterisk 13.22.0 which is relatively painless to upgrade to if you're on 1.8.32.3 or the 1.8 series (at least in our experience) - OR remove contention on the CDR table.
We eventually removed the extra SP we had running on the MySQL / Percona CDR table, as the contention problems persisted with 13.22.0, BUT IT DOES NOT CRASH LIKE 1.8.32.3 - while running against the same Percona 5.6 MySQL version, with the same level of MySQL DB contention taking place.
E. g. look for contention on the MySQL tables you use, or just SQL contention in general - generate enough contention (with tables locked when Asterisk tries to write to them) and it does seem that 1.8 series Asterisk instances will segfault in the ODBC driver, if the concurrent call count goes high enough.
Or (the better option) upgrade to at least Asterisk 13 (in our experience).
Even with the same contention on MySQL db's accessed with unixODBC 2.3.6, and our same table-access killer SP running, Asterisk 13.22.0 doesn't crash at all when writing with the same version unixODBC driver to the contentious tables in MySQL. (We still had the same problem with people only being capable of making one call and then waiting up to five minutes post-hangup before being able to make the next call, but we solved that by not running the SP on schedule anymore against the CDR and CEL tables.)
E.g. effectively we solved the crashes by upgrading from 1.8.32.3 to 13.22.0 - the rest is incidentals unique to our usage case.
Hope this helps.
Date: Thu, 4 Oct 2018 17:10:01 +0200
From: Jonas Kellens <jonas.kellens at telenet.be>
To: Asterisk Users Mailing List - Non-Commercial Discussion
<asterisk-users at lists.digium.com>
Subject: [asterisk-users] Spontaneous reboot due to MySQL lookups ?
Message-ID: <bf23646c-cc52-6744-5748-65727405ff57 at telenet.be>
Content-Type: text/plain; charset="utf-8"; Format="flowed"
Hello
using Asterisk 1.8.32.
I notice that there is a spontaneous reboot of the Asterisk system from time to time.
When I look in the logs (verbose file) I noticed that every time this occurs it's at a moment that there is a MySQL action, be it a lookup or an insert/update/delete.
I must say I do have some MySQL queries that occur in my dialplan when a call comes in, to look up different actions to perform on this call.
An idea how to overcome this problem ? Seems a "performance" issue, no ?!
Is it better to have these MySQL queries to be done by an external
script (like a php script that I call with the System()-command or a
SHELL()-command) ?
Here are some examples from the verbose file.
[Aug 22 15:19:10] VERBOSE[2977] pbx.c: [Aug 22 15:19:10] --
Executing [s at sub-GetAlertInfo:3] MYSQL("SIP/SipAgenT01-0000317d",
"Connect connid localhost myuser mypwd myDB") in new stack
[Aug 22 15:19:10] VERBOSE[2977] pbx.c: [Aug 22 15:19:10] --
Executing [s at sub-GetAlertInfo:5] MYSQL("SIP/SipAgenT01-0000317d", "Query
resultid 1 SELECT uri, callinfo FROM distringtone WHERE onoff='1'") in
new stack
[Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing
'/etc/asterisk/logger.conf': [Aug 22 15:19:18] VERBOSE[3306] config.c:
[Aug 22 15:19:18] == Found
[Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing
'/etc/asterisk/asterisk.conf': [Aug 22 15:19:18] VERBOSE[3306] config.c:
[Aug 22 15:19:18] == Found
[Aug 22 15:19:18] VERBOSE[3306] manager.c: [Aug 22 15:19:18] == Manager
registered action DataGet
[Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing
'/etc/asterisk/codecs.conf': [Aug 22 15:19:18] VERBOSE[3306] config.c:
[Aug 22 15:19:18] == Found
[Aug 22 15:19:18] VERBOSE[3306] loader.c: [Aug 22 15:19:18] Asterisk
Dynamic Loader Starting:
[Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing
'/etc/asterisk/modules.conf': [Aug 22 15:19:18] VERBOSE[3306] config.c:
[Aug 22 15:19:18] == Found
[Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing
'/etc/asterisk/res_config_mysql.conf': [Aug 22 15:19:18] VERBOSE[3306]
config.c: [Aug 22 15:19:18] == Found
[Aug 22 15:19:18] VERBOSE[3306] res_config_mysql.c: [Aug 22 15:19:18]
== MySQL RealTime driver loaded.
[Aug 22 15:19:18] VERBOSE[3306] loader.c: [Aug 22 15:19:18]
res_config_mysql.so => (MySQL RealTime Configuration Driver)
[Aug 22 16:23:25] VERBOSE[24283] pbx.c: [Aug 22 16:23:25] --
Executing [s at sub-GetSipAccountdetails:3]
MYSQL("SIP/SipAgenT01-00004184", "Connect connid localhost myuser mypwd
myDB") in new stack
[Aug 22 16:23:25] VERBOSE[24283] pbx.c: [Aug 22 16:23:25] --
Executing [s at sub-GetSipAccountdetails:4]
MYSQL("SIP/SipAgenT01-00004184", "Query resultid 1 SELECT SIPusername,
currstatus, available FROM tbl_SIP WHERE ID="800"") in new stack
[Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing
'/etc/asterisk/logger.conf': [Aug 22 16:23:32] VERBOSE[24309] config.c:
[Aug 22 16:23:32] == Found
[Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing
'/etc/asterisk/asterisk.conf': [Aug 22 16:23:32] VERBOSE[24309]
config.c: [Aug 22 16:23:32] == Found
[Aug 22 16:23:32] VERBOSE[24309] manager.c: [Aug 22 16:23:32] == Manager
registered action DataGet
[Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing
'/etc/asterisk/codecs.conf': [Aug 22 16:23:32] VERBOSE[24309] config.c:
[Aug 22 16:23:32] == Found
[Aug 22 16:23:32] VERBOSE[24309] loader.c: [Aug 22 16:23:32] Asterisk
Dynamic Loader Starting:
[Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing
'/etc/asterisk/modules.conf': [Aug 22 16:23:32] VERBOSE[24309] config.c:
[Aug 22 16:23:32] == Found
[Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing
'/etc/asterisk/res_config_mysql.conf': [Aug 22 16:23:32] VERBOSE[24309]
config.c: [Aug 22 16:23:32] == Found
[Aug 22 16:23:32] VERBOSE[24309] res_config_mysql.c: [Aug 22 16:23:32]
== MySQL RealTime driver loaded.
[Aug 22 16:23:32] VERBOSE[24309] loader.c: [Aug 22 16:23:32]
res_config_mysql.so => (MySQL RealTime Configuration Driver)
[Oct 4 10:11:25] VERBOSE[4944] pbx.c: [Oct 4 10:11:25] --
Executing [s at sub-settings:16] MYSQL("SIP/SipAgenT01-000008cb", "Connect
connid localhost myuser mypwd myDB") in new stack
[Oct 4 10:11:25] VERBOSE[4944] pbx.c: [Oct 4 10:11:25] --
Executing [s at sub-settings:17] MYSQL("SIP/SipAgenT01-000008cb", "Query
resultid 1 SELECT blockID from DID where DID=987654321") in new stack
[Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Parsing
'/etc/asterisk/asterisk.conf': [Oct 4 10:11:29] VERBOSE[4961] config.c:
[Oct 4 10:11:29] == Found
[Oct 4 10:11:29] VERBOSE[4961] manager.c: [Oct 4 10:11:29] == Manager
registered action DataGet
[Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Parsing
'/etc/asterisk/codecs.conf': [Oct 4 10:11:29] VERBOSE[4961] config.c:
[Oct 4 10:11:29] == Found
[Oct 4 10:11:29] VERBOSE[4961] loader.c: [Oct 4 10:11:29] Asterisk
Dynamic Loader Starting:
[Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Parsing
'/etc/asterisk/modules.conf': [Oct 4 10:11:29] VERBOSE[4961] config.c:
[Oct 4 10:11:29] == Found
[Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Parsing
'/etc/asterisk/res_config_mysql.conf': [Oct 4 10:11:29] VERBOSE[4961]
config.c: [Oct 4 10:11:29] == Found
[Oct 4 10:11:29] VERBOSE[4961] res_config_mysql.c: [Oct 4 10:11:29]
== MySQL RealTime driver loaded.
[Oct 4 10:11:29] VERBOSE[4961] loader.c: [Oct 4 10:11:29]
res_config_mysql.so => (MySQL RealTime Configuration Driver)
Kind regards
Jonas.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20181004/e150402e/attachment-0001.html>
------------------------------
Message: 3
Date: Thu, 4 Oct 2018 17:36:08 +0200
From: Antony Stone <Antony.Stone at asterisk.open.source.it>
To: "Asterisk Users Mailing List - Non-Commercial Discussion"
<asterisk-users at lists.digium.com>
Subject: Re: [asterisk-users] Spontaneous reboot due to MySQL lookups
?
Message-ID: <201810041736.08641.Antony.Stone at asterisk.open.source.it>
Content-Type: Text/Plain; charset="iso-8859-15"
On Thursday 04 October 2018 at 17:10:01, Jonas Kellens wrote:
> Hello
>
> using Asterisk 1.8.32.
Ooh, vintage :)
> I notice that there is a spontaneous reboot of the Asterisk system from
> time to time.
>
> When I look in the logs (verbose file) I noticed that every time this
> occurs it's at a moment that there is a MySQL action, be it a lookup or
> an insert/update/delete.
>
> I must say I do have some MySQL queries that occur in my dialplan when a
> call comes in, to look up different actions to perform on this call.
>
>
> An idea how to overcome this problem ?
I would recommend (a) update to a current and supported version of Asterisk,
and (b) use the ODBC driver.
If the problem persists then with that setup you're more likely to get help
here or be able to file a bug report, but no-one's going to fix a problem in 1.8
now.
Regards,
Antony.
--
3 logicians walk into a bar. The bartender asks "Do you all want a drink?"
The first logician says "I don't know."
The second logician says "I don't know."
The third logician says "Yes!"
Please reply to the list;
please *don't* CC me.
------------------------------
Message: 4
Date: Thu, 4 Oct 2018 11:49:53 -0400
From: John Novack <jnovack at comcast.net>
To: Asterisk Users Mailing List - Non-Commercial Discussion
<asterisk-users at lists.digium.com>, Jonas Kellens
<jonas.kellens at telenet.be>
Subject: Re: [asterisk-users] Spontaneous reboot due to MySQL lookups
?
Message-ID: <763b4ac9-5bbd-4f7a-144c-5cf32b2a339d at comcast.net>
Content-Type: text/plain; charset="utf-8"; Format="flowed"
Woefully out of date.
You really need to put your efforts into at least a modest upgrade
I use version 13 with MySql queries built into the dialplan on CentOs 6 and have NO such issues, either performance or any restart or reboot. It simply works
I never used either 1.6 or 1.8, going from 1.4 to version 11, which did require some syntax changes to the dialplan.
Given that even version 11 is EOL, you really need to put your efforts into doing the migration rather than tracking this one down
JMO
John Novack
Jonas Kellens wrote:
>
> Hello
>
> using Asterisk 1.8.32.
>
> I notice that there is a spontaneous reboot of the Asterisk system from time to time.
>
> When I look in the logs (verbose file) I noticed that every time this occurs it's at a moment that there is a MySQL action, be it a lookup or an insert/update/delete.
>
> I must say I do have some MySQL queries that occur in my dialplan when a call comes in, to look up different actions to perform on this call.
>
>
> An idea how to overcome this problem ? Seems a "performance" issue, no ?!
>
> Is it better to have these MySQL queries to be done by an external script (like a php script that I call with the System()-command or a SHELL()-command) ?
>
>
> Here are some examples from the verbose file.
>
>
>
> [Aug 22 15:19:10] VERBOSE[2977] pbx.c: [Aug 22 15:19:10] -- Executing [s at sub-GetAlertInfo:3] MYSQL("SIP/SipAgenT01-0000317d", "Connect connid localhost myuser mypwd myDB") in new stack
> [Aug 22 15:19:10] VERBOSE[2977] pbx.c: [Aug 22 15:19:10] -- Executing [s at sub-GetAlertInfo:5] MYSQL("SIP/SipAgenT01-0000317d", "Query resultid 1 SELECT uri, callinfo FROM distringtone WHERE onoff='1'") in new stack
> [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing '/etc/asterisk/logger.conf': [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Found
> [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing '/etc/asterisk/asterisk.conf': [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Found
> [Aug 22 15:19:18] VERBOSE[3306] manager.c: [Aug 22 15:19:18] == Manager registered action DataGet
> [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing '/etc/asterisk/codecs.conf': [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Found
> [Aug 22 15:19:18] VERBOSE[3306] loader.c: [Aug 22 15:19:18] Asterisk Dynamic Loader Starting:
> [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing '/etc/asterisk/modules.conf': [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Found
> [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Parsing '/etc/asterisk/res_config_mysql.conf': [Aug 22 15:19:18] VERBOSE[3306] config.c: [Aug 22 15:19:18] == Found
> [Aug 22 15:19:18] VERBOSE[3306] res_config_mysql.c: [Aug 22 15:19:18] == MySQL RealTime driver loaded.
> [Aug 22 15:19:18] VERBOSE[3306] loader.c: [Aug 22 15:19:18] res_config_mysql.so => (MySQL RealTime Configuration Driver)
>
>
>
> [Aug 22 16:23:25] VERBOSE[24283] pbx.c: [Aug 22 16:23:25] -- Executing [s at sub-GetSipAccountdetails:3] MYSQL("SIP/SipAgenT01-00004184", "Connect connid localhost myuser mypwd myDB") in new stack
> [Aug 22 16:23:25] VERBOSE[24283] pbx.c: [Aug 22 16:23:25] -- Executing [s at sub-GetSipAccountdetails:4] MYSQL("SIP/SipAgenT01-00004184", "Query resultid 1 SELECT SIPusername, currstatus, available FROM tbl_SIP WHERE ID="800"") in new stack
> [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing '/etc/asterisk/logger.conf': [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Found
> [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing '/etc/asterisk/asterisk.conf': [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Found
> [Aug 22 16:23:32] VERBOSE[24309] manager.c: [Aug 22 16:23:32] == Manager registered action DataGet
> [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing '/etc/asterisk/codecs.conf': [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Found
> [Aug 22 16:23:32] VERBOSE[24309] loader.c: [Aug 22 16:23:32] Asterisk Dynamic Loader Starting:
> [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing '/etc/asterisk/modules.conf': [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Found
> [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Parsing '/etc/asterisk/res_config_mysql.conf': [Aug 22 16:23:32] VERBOSE[24309] config.c: [Aug 22 16:23:32] == Found
> [Aug 22 16:23:32] VERBOSE[24309] res_config_mysql.c: [Aug 22 16:23:32] == MySQL RealTime driver loaded.
> [Aug 22 16:23:32] VERBOSE[24309] loader.c: [Aug 22 16:23:32] res_config_mysql.so => (MySQL RealTime Configuration Driver)
>
>
>
> [Oct 4 10:11:25] VERBOSE[4944] pbx.c: [Oct 4 10:11:25] -- Executing [s at sub-settings:16] MYSQL("SIP/SipAgenT01-000008cb", "Connect connid localhost myuser mypwd myDB") in new stack
> [Oct 4 10:11:25] VERBOSE[4944] pbx.c: [Oct 4 10:11:25] -- Executing [s at sub-settings:17] MYSQL("SIP/SipAgenT01-000008cb", "Query resultid 1 SELECT blockID from DID where DID=987654321") in new stack
> [Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Parsing '/etc/asterisk/asterisk.conf': [Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Found
> [Oct 4 10:11:29] VERBOSE[4961] manager.c: [Oct 4 10:11:29] == Manager registered action DataGet
> [Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Parsing '/etc/asterisk/codecs.conf': [Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Found
> [Oct 4 10:11:29] VERBOSE[4961] loader.c: [Oct 4 10:11:29] Asterisk Dynamic Loader Starting:
> [Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Parsing '/etc/asterisk/modules.conf': [Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Found
> [Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Parsing '/etc/asterisk/res_config_mysql.conf': [Oct 4 10:11:29] VERBOSE[4961] config.c: [Oct 4 10:11:29] == Found
> [Oct 4 10:11:29] VERBOSE[4961] res_config_mysql.c: [Oct 4 10:11:29] == MySQL RealTime driver loaded.
> [Oct 4 10:11:29] VERBOSE[4961] loader.c: [Oct 4 10:11:29] res_config_mysql.so => (MySQL RealTime Configuration Driver)
>
>
>
>
> Kind regards
>
> Jonas.
>
>
>
>
--
Dog is my Co-pilot
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20181004/34745a47/attachment-0001.html>
------------------------------
Subject: Digest Footer
_______________________________________________
--Bandwidth and Colocation Provided by http://www.api-digital.com--
Check out the new Asterisk community forum at: https://community.asterisk.org/
New to Asterisk? Start here:
https://wiki.asterisk.org/wiki/display/AST/Getting+Started
asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
http://lists.digium.com/mailman/listinfo/asterisk-users
------------------------------
End of asterisk-users Digest, Vol 170, Issue 5
**********************************************
More information about the asterisk-users
mailing list