[Home]

Summary:ASTERISK-28166: app_voicemail: Asterisk unresponsive after changing voicemail password with ODBC
Reporter:Michael (ringo)Labels:patch pjsip
Date Opened:2018-11-15 21:01:59.000-0600Date Closed:2019-03-01 15:26:00.000-0600
Priority:MinorRegression?
Status:Closed/CompleteComponents:Applications/app_voicemail Resources/res_config_odbc Resources/res_odbc
Versions:16.0.0 Frequency of
Occurrence
Constant
Related
Issues:
Environment:debian 9 amd64 asterisk v16 LTS using pjsip mysql ODBCAttachments:( 0) 0001-res_config_odbc-Avoid-deadlock-when-max_connections-.patch
( 1) asterisk.tar.gz
( 2) extconfig.conf
( 3) res_odbc.conf
Description:i have 2 fresh installs of the latest v16 LTS on debian 9 using pjsip config setup in mysql through odbc driver mysql-connector-odbc-8.0.11.

When I change voicemail password, at the time the new password would get writen into sql table, asterisk stops responding and must be killed -9 and restarted in order to resume normal opteration.

This happens 100% of the time on 2 identical fresh installs.

when using voicemail config in plain text file, this doesn't seem to happen.
{noformat}
[Nov 15 21:46:14] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 53 (5), at #.#.#.#:16408
[Nov 15 21:46:14] DEBUG[20748] threadpool.c: Increasing threadpool stasis-core's size by 1
[Nov 15 21:46:14] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating END DTMF Frame: 53 (5), at #.#.#.#:16408
[Nov 15 21:46:14] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov 15 21:46:14] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov 15 21:46:14] DEBUG[16091][C-00000004] channel.c: Channel PJSIP/XXXXX-00000003 setting write format path: g722 -> g722
[Nov 15 21:46:14] DEBUG[16091][C-00000004] media_cache.c: Failed to obtain media at 'vm-newpassword'
[Nov 15 21:46:14] DEBUG[16091][C-00000004] channel.c: Channel PJSIP/XXXXX-00000003 setting write format path: g722 -> g722
[Nov 15 21:46:14] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Nov 15 21:46:14] VERBOSE[16091][C-00000004] file.c: <PJSIP/XXXXX-00000003> Playing 'vm-newpassword.g722' (language 'en')
[Nov 15 21:46:18] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (82 requested / 82 actual) timer ticks per second
[Nov 15 21:46:18] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov 15 21:46:18] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov 15 21:46:18] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov 15 21:46:18] DEBUG[16091][C-00000004] channel.c: Channel PJSIP/XXXXX-00000003 setting write format path: g722 -> g722
[Nov 15 21:46:19] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:19] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating END DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:19] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:19] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating END DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:19] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:19] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating END DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:20] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 35 (#), at #.#.#.#:16408
[Nov 15 21:46:20] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating END DTMF Frame: 35 (#), at #.#.#.#:16408
[Nov 15 21:46:20] DEBUG[16091][C-00000004] media_cache.c: Failed to obtain media at 'vm-reenterpassword'
[Nov 15 21:46:20] DEBUG[16091][C-00000004] channel.c: Channel PJSIP/XXXXX-00000003 setting write format path: g722 -> g722
[Nov 15 21:46:20] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Difference is 22248, ms is 2801
[Nov 15 21:46:20] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Nov 15 21:46:20] VERBOSE[16091][C-00000004] file.c: <PJSIP/XXXXX-00000003> Playing 'vm-reenterpassword.g722' (language 'en')
[Nov 15 21:46:21] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:21] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating END DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:21] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov 15 21:46:21] DEBUG[16091][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov 15 21:46:21] DEBUG[16091][C-00000004] channel.c: Channel PJSIP/XXXXX-00000003 setting write format path: g722 -> g722
[Nov 15 21:46:22] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:22] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating END DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:22] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:22] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating END DTMF Frame: 52 (4), at #.#.#.#:16408
[Nov 15 21:46:22] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 35 (#), at #.#.#.#:16408
[Nov 15 21:46:22] DEBUG[16091][C-00000004] res_rtp_asterisk.c: Creating END DTMF Frame: 35 (#), at #.#.#.#:16408
[Nov 15 21:46:22] DEBUG[16091][C-00000004] res_odbc.c: Reusing ODBC handle 0x7f8c50003388 from class 'sqlP'
{noformat}
Comments:By: Asterisk Team (asteriskteam) 2018-11-15 21:02:01.089-0600

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: Michael (ringo) 2018-11-16 13:34:57.544-0600

In an attempt to narrow down/work around, I have disabled the changing of the password within app_voicemail.c

ie..
vm_change_password(vmu, newpassword);)

and the crashing no longer happens.

By: Michael (ringo) 2018-11-16 13:48:49.706-0600

moving further, disabled right in the password change function for realtime, in the app_voicemail.  Not crashing.

static int change_password_realtime(struct ast_vm_user *vmu, const char *password)
{
       int res = -1;
       if (!strcmp(vmu->password, password)) {
               /* No change (but an update would return 0 rows updated, so we opt out here) */
               return 0;
       }  
ast_log(AST_LOG_NOTICE, "realtime config password changes disabled. - ringo\n");
return 0;



By: Kevin Harwell (kharwell) 2018-11-16 15:45:51.914-0600

Thank you for the crash report. However, we need more information to investigate the crash. Please provide:

1. A backtrace generated from a core dump using the instructions provided on the Asterisk wiki [1].
2. Configuration information necessary to reproduce the crash. For instance in this case can you post the row data for the record you are trying to update?

Thanks!

[1]: https://wiki.asterisk.org/wiki/display/AST/Getting+a+Backtrace

By: Michael (ringo) 2018-11-19 11:47:01.534-0600

1. With this one, asterisk doesn’t actually stop.  it’s still running.  The call with the app_voicemail stops but stays open.  It never seems to timeout.  Asterisk still remains running in the background but does not respond to calls.  Registration to the phone is lost.  The asterisk console will still respond for a bit.  I can quickly run “module show” and see the modules.  This time, I tried “module reload app_voicemail.so” which seemed to make it even more mad, as now “module show” shows nothing.  Lastly, doing a “mod” + tab complete just halted the asterisk cli now.

2.
{noformat}
| uniqueid | context | mailbox | password | fullname | alias | email           | pager | attach | attachfmt | serveremail | language | tz   | deletevoicemail | saycid | sendvoicemail | review | tempgreetwarn | operator | envelope | sayduration | forcename | forcegreetings | callback | dialout | exitcontext | maxmsg | volgain | imapuser | imappassword | imapserver | imapport | imapflags | stamp |
+----------+---------+---------+----------+----------+-------+-----------------+-------+--------+-----------+-------------+----------+------+-----------------+--------+---------------+--------+---------------+----------+----------+-------------+-----------+----------------+----------+---------+-------------+--------+---------+----------+--------------+------------+----------+-----------+-------+
|     1387 | viapbx  | 5250    | 456      | Mike R   | NULL  | ringo@vianet.ca | NULL  | no     | NULL      | NULL        | NULL     | NULL | NULL            | no     | NULL          | NULL   | NULL          | NULL     | no       |        NULL | NULL      | NULL           | NULL     | NULL    | NULL        |   NULL |    NULL | NULL     | NULL         | NULL       | NULL     | NULL      | NULL  |
{noformat}


I just noticed, the password DOES CHANGE in the sql right away as soon as I hit pound using the #5 option.  

By: Joshua C. Colp (jcolp) 2018-11-20 06:40:14.421-0600

Your original report stated that a crash occurred, but now you state it freezes. Both still need a backtrace[1] to show what is going on. The freeze would be considered a deadlock.

[1] https://wiki.asterisk.org/wiki/display/AST/Getting+a+Backtrace

By: Michael (ringo) 2018-11-20 15:39:48.976-0600

I think i got it now. Hope this helps.  Thanks.

By: Benjamin Keith Ford (bford) 2018-11-26 14:42:08.030-0600

On 16 branch I'm unable to reproduce this. I have my voicemail configured to use ODBC realtime, and change the password with an UPDATE command. Asterisk seems to still be working fine. Can you:
# Provide which database back-end you're using, and
# Explain exactly what it is you're doing to produce this lockup, if different from the scenario I worked through above

By: Michael (ringo) 2018-11-26 20:11:22.289-0600

I was refering to changing password from within the VoiceMailMain Application.  Not directly using sql UPDATE.


1. Database, mysql using unixodbc package, and mysql-connector-odbc-8.0.11-linux-debian9-x86-64bit.tar.gz driver since that is not included in debian9.

2. after logging into mailbox using VoiceMailMain app, selecting option 0 for "mailbox options", then 5 for "change your password".  After typing a matching password twice, and is accepted, when the system goes to update the sql database, it at that point locks up.

By: Michael (ringo) 2018-11-27 20:13:00.258-0600

I was refering to changing password from within the VoiceMailMain Application. Not directly using sql UPDATE.

1. Database, mysql using unixodbc package, and mysql-connector-odbc-8.0.11-linux-debian9-x86-64bit.tar.gz driver since that is not included in debian9.

2. after logging into mailbox using VoiceMailMain app, selecting option 0 for "mailbox options", then 5 for "change your password". After typing a matching password twice, and is accepted, when the system goes to update the sql database, it at that point locks up.


By: Benjamin Keith Ford (bford) 2018-11-28 11:01:39.330-0600

Tried your method with both mysql and postgres, but unfortunately could not produce the same result. Can you attach your res_odbc.conf and extconfig.conf files?

By: Michael (ringo) 2018-11-28 11:41:16.862-0600

files attached.





By: Michael (ringo) 2018-12-03 18:12:29.690-0600

i have configured res_config_mysql.conf along side my odbc to mysql setup and when I switch to it, it seems to work fine.

[settings]
voicemail => mysql,hpbx4sqlP,voicemail,1

but switching back to this fail:
[settings]
voicemail => odbc,hpbx4sqlP,voicemail,1


By: Michael (ringo) 2018-12-03 19:48:54.972-0600

currently using mysql-connector-odbc-8.0.13-linux-debian9-x86-64bit.tar.gz

tried mariadb-connector-odbc-3.0.7-ga-debian-x86_64.tar.gz which doesn't seem to connect at all which i think is what caused me to try the mysql-connector in the first place.

downgraded to mariadb-connector-odbc-2.0.18-ga-debian-x86_64.tar.gz which does connect, but I still get the asterisk lockup when changing voicemail pin number via VoicemailMain.

By: Joshua C. Colp (jcolp) 2018-12-10 08:45:15.692-0600

The problem here is due to the usage of ast_update2_realtime by app_voicemail. That function appears to contain a bug whereby a deadlock will occur as it waits for a database connection it can never get using the default configuration. The prepare callback, update2_prepare, calls ast_odbc_find_table which attempts to get the database connection. This database connection is instead already retrieved and used by update2_odbc. Increasing the number of maximum connections and using a latest unixodbc may work around the problem.

By: Michael (ringo) 2018-12-17 18:52:29.394-0600

tried asterisk...
v15.7.0 fail
v13.21-cert3 fail
even tried v16.1.0 installed in debian jessie.  Fail.

I noticed just by chance that it is failing after i reload asterisk config.  If i just start up asterisk from a stopped state, it does NOT lock up.  It's only after asterisk has been reloaded ie. 'core reload' that causes these failures.

this behaviour doesn't happen when using realtime sql through the mysql driver and res_config_mysql.conf.  Only when using through the odbc driver and res_odbc.conf.


By: Michael (ringo) 2018-12-27 16:32:12.465-0600

I GOT IT!!

I didn't have a "max_connections" setting in my res_odbc.conf.

as per example in the res_odbc.conf sample config:
max_connections => 5

as per note in the res_odbc.conf sample config:
; The maximum number of connections to have open at any given time.
; This defaults to 1 and it is highly recommended to only set this higher
; if using a version of UnixODBC greater than 2.3.1.
;max_connections => 20


I set max_connections => 20 and this symptom goes away.

So, i guess since the default is 1, having only 1 connection is causing problems with realtime app_voicemail?



By: Joshua C. Colp (jcolp) 2018-12-27 17:20:32.096-0600

Yes, and I mentioned that change as a potential workaround in my analysis.

By: Michael (ringo) 2018-12-27 19:31:43.680-0600

lol ya a lot of this is kinda jiberish to me.  I'm still kinda new to Asterisk.  Now that I know it, i see you said increase connections. At the time i thought you were talking about some internal code stuff not something i could have changed myself.   Hind-sight is 20/20. lol Thanks for everything.  This really is a great piece of software!


By: Michael (ringo) 2019-01-30 22:56:21.229-0600

configuring max_connections=>20 in res_odbc.conf seemed to do the trick for this.  max_connections default apparently is 1.  Maybe the default value if not configured could be changed to something > 1.  Otherwise, this can be closed.


By: Joshua C. Colp (jcolp) 2019-01-31 04:21:34.325-0600

There is still an underlying bug here so this will remain open.

As for changing the default - it's 1 because versions of UnixODBC 2.3.1 or lower has a bug where having multiple connections can leak memory and cause crashes.

By: Sean Bright (seanbright) 2019-02-27 19:24:38.329-0600

[~ringo] - can you test the patch that is up for review here:

https://gerrit.asterisk.org/c/asterisk/+/11059

And let us know if it fixes the problem if you have {{max_connections}} set to {{1}}?

By: Michael (ringo) 2019-02-28 11:33:16.095-0600

what source version do I patch to?  tried with v16.0.0 and v16.1.0.  getting hunk failed errors.



By: Sean Bright (seanbright) 2019-02-28 12:22:32.081-0600

I've attached [^0001-res_config_odbc-Avoid-deadlock-when-max_connections-.patch] which should apply cleanly against 16.2.

By: Michael (ringo) 2019-02-28 14:44:08.040-0600

installed v16.2.0
commented out "max_connections => 20" in my config
tested and failed to confirm problem.
applied patch recompiled.
tested again, success!!!

Looks good!


By: Sean Bright (seanbright) 2019-02-28 14:56:07.280-0600

Thanks for testing [~ringo]!

By: Michael (ringo) 2019-02-28 16:07:20.504-0600

no problem!  thanks for the great work.

By: Friendly Automation (friendly-automation) 2019-03-01 15:26:01.276-0600

Change 11059 merged by Friendly Automation:
res_config_odbc: Avoid deadlock when max_connections = 1

[https://gerrit.asterisk.org/c/asterisk/+/11059|https://gerrit.asterisk.org/c/asterisk/+/11059]

By: Friendly Automation (friendly-automation) 2019-03-01 16:22:24.183-0600

Change 11076 merged by Kevin Harwell:
res_config_odbc: Avoid deadlock when max_connections = 1

[https://gerrit.asterisk.org/c/asterisk/+/11076|https://gerrit.asterisk.org/c/asterisk/+/11076]

By: Friendly Automation (friendly-automation) 2019-03-01 16:22:53.616-0600

Change 11075 merged by Kevin Harwell:
res_config_odbc: Avoid deadlock when max_connections = 1

[https://gerrit.asterisk.org/c/asterisk/+/11075|https://gerrit.asterisk.org/c/asterisk/+/11075]