Stefan Viljoen
2018-Oct-05 06:12 UTC
[asterisk-users] Spontaneous reboot due to MySQL lookups ? (Jonas Kellens)
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
**********************************************