[Home]

Summary:ASTERISK-08154: [patch] voicemail playback via odbc connection gives segfault
Reporter:Caio Begotti (caio1982)Labels:
Date Opened:2006-11-20 11:05:53.000-0600Date Closed:2006-12-08 07:56:09.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_voicemail
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 20061120__bug8385__trunk.diff.txt
( 1) 20061120__bug8385.diff.txt
( 2) 20061201__bug8385.diff.txt
( 3) backtrace-full.txt
( 4) report_vm_session.txt
Description:After recording a voicemail message to a new user I tried to playback the recorded file and it didn't work. The object ID in my PostgreSQL database (using the ODBC connector for Asterisk) seems ok. In fact I've exported it manually and the file is recording is there.

The voicemail application even recognizes the messages number and tell me that there is a new message (only 1) in my mailbox but then it segfaults with no more information. I've tried both gdb and strace, to check the core file for more tips and perhaps some wrong call. In vain :-/

My Realtime Static schema is working fine with others Asterisk's features but this one, and the CLI just hangs after playing the "vm-message" file (GSM format). Please let me know what else I can do to debug it a little bit more.
Comments:By: Caio Begotti (caio1982) 2006-11-20 11:08:55.000-0600

I should point out that I've been trying to use it with Realtime Static since the last week, when Corydon told me on IRC that he has fixed a segfault when loading the app_voicemail compiled with ODBC storage. IIRC, that was a bunch of "ast_" addition to some functions.
By: Caio Begotti (caio1982) 2006-11-20 11:31:14.000-0600

The required backtrace:

[...]
Core was generated by `asterisk -gcvvvddd'.
Program terminated with signal 11, Segmentation fault.
#0  0xa7b4a776 in memset () from /lib/tls/libc.so.6

(gdb) bt
#0  0xa7b4a776 in memset () from /lib/tls/libc.so.6
#1  0xa655b544 in retrieve_file (dir=0xa61daf3c "/var/spool/asterisk/voicemail/default/5050/INBOX", msgnum=0) at app_voicemail.c:1116
#2  0xa65680ef in play_message (chan=0x8262080, vmu=0xa61db35c, vms=0xa61dae9c) at app_voicemail.c:4543
#3  0xa657093c in vm_execmain (chan=0x8262080, data=0xa61dffc8) at app_voicemail.c:6394
#4  0x080e47d9 in pbx_extension_helper (c=0x8262080, con=<value optimized out>, context=0x82622a4 "extensions", exten=0x82622f4 "*98", priority=3, label=0x0,
   callerid=0x825db20 "5050", action=E_SPAWN) at pbx.c:503
ASTERISK-1  0x080e668c in __ast_pbx_run (c=0x8262080) at pbx.c:2162
ASTERISK-2  0x080e775f in pbx_thread (data=0x8262080) at pbx.c:2475
ASTERISK-3  0x08117920 in dummy_start (data=0x8262758) at utils.c:545
ASTERISK-4  0xa7d7f0bd in start_thread () from /lib/tls/libpthread.so.0
ASTERISK-5  0xa7ba992e in clone () from /lib/tls/libc.so.6
(gdb) weon:~#
By: Tilghman Lesher (tilghman) 2006-11-20 12:01:47.000-0600

Please apply this patch and check that it solves your issue.
By: Caio Begotti (caio1982) 2006-11-20 12:29:47.000-0600

The segfault is gone, thank you Corydon. But yet I cannot hear the message from my database. That's the relevant part of the full log:

[Nov 21 00:19:55] WARNING[29161] file.c: Unable to open format wav49
[Nov 21 00:19:55] WARNING[29161] file.c: Unable to open /var/spool/asterisk/voicemail/default/5050/Old/msg0000 (format 0x4 (ulaw)): No such file or directory
[Nov 21 00:19:55] DEBUG[29161] app.c: Locked path '/var/spool/asterisk/voicemail/default/5050/Old'
[Nov 21 00:19:55] DEBUG[29161] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/5050/Old'
[Nov 21 00:19:55] DEBUG[29161] pbx.c: Spawn extension (extensions,*98,2) exited non-zero on 'SIP/5050-08227600'
[Nov 21 00:19:55] VERBOSE[29161] logger.c:   == Spawn extension (extensions, *98, 2) exited non-zero on 'SIP/5050-08227600'

This message should have been exported from my Realtime Static schema, not directly from the filesystem, right? The application thinks the message has been successfully reviewed and mark it as "old", but it hasn't. The voicemail app only prompted me with the message info (date, hour and origin).

The message is still there, in my database:

database_name=# select lo_export(recording,'/tmp/recording-97947293.wav') as recording from tb_voicemail_messages where msgnum = 0;

# file /tmp/recording-97947293.wav
/tmp/recording-97947293.wav: RIFF (little-endian) data, WAVE audio, GSM 6.10, mono 8000 Hz

My voicemail/default/5050 dir in the Asterisk' spool has no voice messages.
By: Tilghman Lesher (tilghman) 2006-11-20 12:39:12.000-0600

You should have seen a WARNING relating to mmap().  What was that warning?
By: Caio Begotti (caio1982) 2006-11-20 12:44:58.000-0600

No warnings, really. Just Asterisk calling my own hangup macro and doing the usual CDR cleanup.
By: Caio Begotti (caio1982) 2006-11-20 12:55:36.000-0600

Sorry, the message warning was saved before the message info:

[Nov 21 00:10:23] WARNING[25337] app_voicemail.c: Could not mmap the output file: Cannot allocate memory (12)
[Nov 21 00:10:23] VERBOSE[25337] logger.c:   == Parsing '/var/spool/asterisk/voicemail/default/5050/INBOX/msg0000.txt': [Nov 21 00:10:23] DEBUG[25337] config.c: Parsing /var/spool/asterisk/voicemail/default/5050/INBOX/msg0000.txt
By: Caio Begotti (caio1982) 2006-11-20 12:58:31.000-0600

Resources resume:

*CLI> ulimit
Cpu time (-t) is effectively unlimited.
File size (-f) is effectively unlimited.
Program data segment (-d) is effectively unlimited.
Program stack size (-s) is effectively unlimited.
Core file size (-c) is effectively unlimited.
Resident memory (-m) is effectively unlimited.
Number of processes (-u) is effectively unlimited.
Amount of memory locked into RAM (-l) is effectively unlimited.
Number of file descriptors (-n) is limited to 1024.
Virtual memory (-v) is effectively unlimited.
By: Caio Begotti (caio1982) 2006-11-20 13:09:47.000-0600

I moved the old message back to my inbox directory and then:

[Nov 21 01:05:01] WARNING[3765] file.c: Unable to open /var/spool/asterisk/voicemail/default/5050/INBOX/msg0000 (format 0x4 (ulaw)): No such file or directory
[Nov 21 01:05:01] DEBUG[3765] app.c: Locked path '/var/spool/asterisk/voicemail/default/5050/INBOX'
[Nov 21 01:05:01] DEBUG[3765] app.c: Locked path '/var/spool/asterisk/voicemail/default/5050/Old'
[Nov 21 01:05:01] WARNING[3765] app_voicemail.c: SQL Execute error!
[DELETE FROM tb_voicemail_messages WHERE dir=? AND msgnum=?]

A delete command? Is it right? I was actually reviewing the message after moving it from my web application.
By: Tilghman Lesher (tilghman) 2006-11-20 14:04:27.000-0600

Patch committed to 1.2 in 47862, merged to 1.4 in 47863, merged to trunk in 47866.
By: Caio Begotti (caio1982) 2006-11-30 20:03:09.000-0600

Corydon, I believe this ticket can be reopened since I've been testing this environment using the latest trunk (checked out minutes ago) and the bug is still active and the storage of voicemail messages using ODBC is still faulty then. The full log of my call to listen to the newest message recorded follows:

   -- Executing [*98@extensions:2] VoiceMailMain("SIP/5050-08234440", "@default") in new stack
   -- Playing 'vm-login' (language 'pt_BR')
   -- Playing 'vm-password' (language 'pt_BR')
   -- Playing 'vm-youhave' (language 'pt_BR')
   -- Playing 'digits/1F' (language 'pt_BR')
   -- Playing 'vm-message' (language 'pt_BR')
   -- Playing 'vm-INBOXs' (language 'pt_BR')
   -- Playing 'vm-onefor' (language 'pt_BR')
   -- Playing 'vm-first' (language 'pt_BR')
   -- Playing 'vm-message' (language 'pt_BR')
[Nov 30 23:02:58] WARNING[22883]: app_voicemail.c:1114 retrieve_file: Could not mmap the output file: Cannot allocate memory (12)
 == Parsing '/var/spool/asterisk/voicemail/default/5050/INBOX/msg0000.txt': Found
   -- Playing 'vm-received' (language 'pt_BR')
Really destroying SIP dialog '6b741d9a4d0772fa@aGF3YWlpLmxvY2Fs' Method: REGISTER
Really destroying SIP dialog '69b1557a692f1c6273197597101e7e86@172.16.0.187' Method: NOTIFY
   -- Playing 'digits/day-5' (language 'pt_BR')
   -- Playing 'digits/1' (language 'pt_BR')
Really destroying SIP dialog '0120a71d62ce61415fda09445b2fcb31@172.16.0.187' Method: OPTIONS
   -- Playing 'digits/pt-de' (language 'pt_BR')
Really destroying SIP dialog '4ff4e22d4262da8851af520707a7afca@172.16.0.187' Method: OPTIONS
   -- Playing 'digits/mon-11' (language 'pt_BR')
   -- Playing 'digits/pt-de' (language 'pt_BR')
   -- Playing 'digits/2' (language 'pt_BR')
   -- Playing 'digits/1000' (language 'pt_BR')
   -- Playing 'digits/pt-e' (language 'pt_BR')
   -- Playing 'digits/6' (language 'pt_BR')
   -- Playing 'digits/pt-as' (language 'pt_BR')
   -- Playing 'digits/1F' (language 'pt_BR')
   -- Playing 'digits/hour' (language 'pt_BR')
   -- Playing 'digits/0' (language 'pt_BR')
   -- Playing 'digits/minute' (language 'pt_BR')
   -- Playing 'vm-from-phonenumber' (language 'pt_BR')
   -- Playing 'digits/4' (language 'pt_BR')
   -- Playing 'digits/0' (language 'pt_BR')
   -- Playing 'digits/0' (language 'pt_BR')
[Nov 30 23:03:11] WARNING[22883]: format_wav_gsm.c:122 check_header: Does not begin with RIFF
[Nov 30 23:03:11] WARNING[22883]: file.c:312 fn_wrapper: Unable to open format wav49
[Nov 30 23:03:11] WARNING[22883]: format_wav_gsm.c:122 check_header: Does not begin with RIFF
[Nov 30 23:03:11] WARNING[22883]: file.c:312 fn_wrapper: Unable to open format wav49
[Nov 30 23:03:11] WARNING[22883]: file.c:808 ast_streamfile: Unable to open /var/spool/asterisk/voicemail/default/5050/INBOX/msg0000 (format 0x4 (ulaw)): No such file or directory[Nov 30 23:03:11] WARNING[22883]: app_voicemail.c:1325 delete_file: SQL Execute error!
[DELETE FROM tb_voicemail_messages WHERE dir=? AND msgnum=?]

 == Spawn extension (extensions, *98, 2) exited non-zero on 'SIP/5050-08234440'
   -- Executing [h@extensions:1] Goto("SIP/5050-08234440", "hangupcall|s|1") in new stack
   -- Goto (hangupcall,s,1)
   -- Executing [s@hangupcall:1] ResetCDR("SIP/5050-08234440", "w") in new stack
      > cdr_odbc: Query Successful!
   -- Executing [s@hangupcall:2] NoCDR("SIP/5050-08234440", "") in new stack
[Nov 30 23:03:11] WARNING[22883]: cdr.c:424 ast_cdr_free: CDR on channel 'SIP/5050-08234440' not posted
[Nov 30 23:03:11] WARNING[22883]: cdr.c:426 ast_cdr_free: CDR on channel 'SIP/5050-08234440' lacks end
   -- Executing [s@hangupcall:3] Wait("SIP/5050-08234440", "1") in new stack
   -- Executing [s@hangupcall:4] Hangup("SIP/5050-08234440", "") in new stack
 == Spawn extension (hangupcall, s, 4) exited non-zero on 'SIP/5050-08234440'
Really destroying SIP dialog 'B5DB8DF6-1DD1-11B2-B7C2-8DE6FC77771D@172.16.0.195'

If I try to export the message data (object id) from the PostgreSQL's database, it works and I can hear the message saved. Please let me know how could I improve the quality of the log/report!
By: Tilghman Lesher (tilghman) 2006-12-01 12:32:05.000-0600

I've been experimenting with this code in a trunk branch.  You're welcome to try it.  Needs latest 1.2 SVN.
By: Tilghman Lesher (tilghman) 2006-12-01 12:33:11.000-0600

Changing to minor, since it no longer crashes.
By: Caio Begotti (caio1982) 2006-12-01 13:05:16.000-0600

1.2 SVN? You meant 1.4, right? :-) I'll take a look at it now, thanks.
By: Caio Begotti (caio1982) 2006-12-01 13:11:46.000-0600

I'm sorry Corydon but I couldn't locate new files related to this in my svn update right now (from trunk).
Could you please confirm to me if it's in 1.4 trunk, 1.4 branch or you were serious about 1.2?
By: Tilghman Lesher (tilghman) 2006-12-01 14:20:20.000-0600

The patch file applies to 1.2.
By: Caio Begotti (caio1982) 2006-12-01 14:44:15.000-0600

I thought only security fixes were getting merged in the 1.2 tree.
Do you have any idea about it in the Asterisk 1.4, Corydon?
By: Tilghman Lesher (tilghman) 2006-12-01 15:14:27.000-0600

No... bug fixes will still get committed to 1.2.  I think you're confusing bug fixes with new features.  New features are expressly prohibited in any released branch.
By: Caio Begotti (caio1982) 2006-12-01 15:21:35.000-0600

But what I meant was "if the voicemail with ODBC storage is available in 1.4 but isn't working well (in fact not working at all), i thought that would/could be fixed in 1.4, not in 1.2" :-)
By: Serge Vecher (serge-v) 2006-12-01 15:51:42.000-0600

caio1982: just download the 1.2 svn branch and test the patch, please. Thanks!
By: Caio Begotti (caio1982) 2006-12-01 18:02:28.000-0600

A little bit of skepticism doesn't hurt! It worked like a charm :-D what now for 1.4?
By: Serge Vecher (serge-v) 2006-12-02 14:46:56.000-0600

cool, thanks for testing. Hopefully this patch will get committed and fixed in 1.2/1.4/trunk soon.
By: Tilghman Lesher (tilghman) 2006-12-04 19:42:26.000-0600

Merged in 48251.
By: Caio Begotti (caio1982) 2006-12-07 11:59:50.000-0600

Corydon, that's a kind of weird behavior. It worked fine with 1.2 and the patch, but with 1.4 (both branch and trunk code) I can't get this to work right. The log messages and the issue remains the same as specified in previous messages above.

Anyway, what about the longblob type that another tester talked about in a related ticket? He said Asterisk is using it and it's incompatible with PGSQL.
By: Tilghman Lesher (tilghman) 2006-12-07 13:00:28.000-0600

So are you still getting an mmap error?
By: Caio Begotti (caio1982) 2006-12-07 13:15:02.000-0600

To be honest, I didn't understand that well when I'll certainly get the mmap error message but no, it's not in my logs (I just 'grep -i mmap' them). Anyway, the voicemail messages are being inserted right in PostgreSQL (psql mydb -c '\dl' reports correctly my large objects count). I've attached one more log to this ticket, with the current situation.
By: Tilghman Lesher (tilghman) 2006-12-07 13:46:42.000-0600

Please followup in ASTERISK-8276, as this issue is, in fact, fixed, and your issue is identical to the one expressed there.
By: Caio Begotti (caio1982) 2006-12-08 05:59:01.000-0600

Corydon, you wrote in the ticket 8513 that "this is an issue with the Postgresql ODBC driver. It will need to be reported upstream that we are unable to use ODBC to store blob fields" but I've tried the 1.2 patch and it worked fine. Using exactly the same version of PGSQL and the ODBC driver.

Only the code of app_voicemail.c changed and it worked. Well... is there some workaround for it since you guys think that's not fixable even so? I don't think the maintainers of the ODBC connector will release a patch or a new version because that just in time before the new Debian Etch release, which worry me a lot, especially because it worked with 1.2 as stated.
By: Tilghman Lesher (tilghman) 2006-12-08 07:56:09.000-0600

Please update to 8513, not this one.  Do not reopen this bug without first contacting a bug marshal.