From 38d5970b697ebf3881bebb48c6fcdfa2800783e3 Mon Sep 17 00:00:00 2001 From: George Joseph Date: Tue, 9 Apr 2024 07:23:36 -0600 Subject: [PATCH] app_voicemail_odbc: Allow audio to be kept on disk This commit adds a new voicemail.conf option 'odbc_audio_on_disk' which when set causes the ODBC variant of app_voicemail to leave the message and greeting audio files on disk and only store the message metadata in the database. This option came from a concern that the database could grow to large and cause remote access and/or replication to become slow. In a clustering situation with this option, all asterisk instances would share the same database for the metadata and either use a shared filesystem or other filesystem replication service much more suitable for synchronizing files. The changes to app_voicemail to implement this feature were actually quite small but due to the complexity of the module, the actual source code changes were greater. They fall into the following categories: * Tracing. The module is so complex that it was impossible to figure out the path taken for various scenarios without the addition of many SCOPE_ENTER, SCOPE_EXIT and ast_trace statements, even in code that's not related to the functional change. Making this worse was the fact that many "if" statements in this module didn't use braces. Since the tracing macros add multiple statements, many "if" statements had to be converted to use braces. * Excessive use of PATH_MAX. Previous maintainers of this module used PATH_MAX to allocate character arrays for filesystem paths and SQL statements as though they cost nothing. In fact, PATH_MAX is defined as 4096 bytes! Some functions had (and still have) multiples of these. One function has 7. Given that the vast majority of installations use the default spool directory path `/var/spool/asterisk/voicemail`, the actual path length is usually less than 80 bytes. That's over 4000 bytes wasted. It was the same for SQL statement buffers. A 4K buffer for statement that only needed 60 bytes. All of these PATH_MAX allocations in the ODBC related code were changed to dynamically allocated buffers. The rest will have to be addressed separately. * Bug fixes. During the development of this feature, several pre-existing ODBC related bugs were discovered and fixed. They had to do with leaving orphaned files on disk, not preserving original message ids when moving messages between folders, not honoring the "formats" config parameter in certain circumstances, etc. UserNote: This commit adds a new voicemail.conf option 'odbc_audio_on_disk' which when set causes the ODBC variant of app_voicemail_odbc to leave the message and greeting audio files on disk and only store the message metadata in the database. Much more information can be found in the voicemail.conf.sample file. --- apps/app_voicemail.c | 1244 +++++++++++++++++-------- configs/samples/voicemail.conf.sample | 91 +- main/app.c | 20 +- 3 files changed, 965 insertions(+), 390 deletions(-) diff --git a/apps/app_voicemail.c b/apps/app_voicemail.c index 9e067d0daa4..81c46b53feb 100644 --- a/apps/app_voicemail.c +++ b/apps/app_voicemail.c @@ -689,10 +689,14 @@ static AST_LIST_HEAD_STATIC(vmstates, vmstate); #define VM_FWDURGAUTO (1 << 18) /*!< Autoset of Urgent flag on forwarded Urgent messages set globally */ #define VM_EMAIL_EXT_RECS (1 << 19) /*!< Send voicemail emails when an external recording is added to a mailbox */ #define VM_MARK_URGENT (1 << 20) /*!< After recording, permit the caller to mark the message as urgent */ +#define VM_ODBC_AUDIO_ON_DISK (1 << 21) /*!< When using ODBC, leave the message and greeting recordings on disk instead of moving them into the table */ + #define ERROR_LOCK_PATH -100 #define ERROR_MAX_MSGS -101 #define OPERATOR_EXIT 300 +#define MSGFILE_LEN (7) /*!< Length of the message file name: msgXXXX */ + enum vm_box { NEW_FOLDER = 0, OLD_FOLDER = 1, @@ -978,13 +982,16 @@ struct vm_state { #ifdef ODBC_STORAGE static char odbc_database[80] = "asterisk"; static char odbc_table[80] = "voicemessages"; -#define RETRIEVE(a,b,c,d) retrieve_file(a,b) -#define DISPOSE(a,b) remove_file(a,b) -#define STORE(a,b,c,d,e,f,g,h,i,j,k) store_file(a,b,c,d) -#define EXISTS(a,b,c,d) (message_exists(a,b)) -#define RENAME(a,b,c,d,e,f,g,h) (rename_file(a,b,c,d,e,f)) -#define COPY(a,b,c,d,e,f,g,h) (copy_file(a,b,c,d,e,f)) -#define DELETE(a,b,c,d) (delete_file(a,b)) +size_t odbc_table_len = sizeof(odbc_table); +#define COUNT(a, b) odbc_count_messages(a,b) +#define LAST_MSG_INDEX(a) odbc_last_message_index(a) +#define RETRIEVE(a,b,c,d) odbc_retrieve_message(a,b) +#define DISPOSE(a,b) odbc_remove_files(a,b) +#define STORE(a,b,c,d,e,f,g,h,i,j,k) odbc_store_message(a,b,c,d) +#define EXISTS(a,b,c,d) (odbc_message_exists(a,b)) +#define RENAME(a,b,c,d,e,f,g,h) (odbc_rename_message(a,b,c,d,e,f)) +#define COPY(a,b,c,d,e,f,g,h) (odbc_copy_message(a,b,c,d,e,f)) +#define DELETE(a,b,c,d) (odbc_delete_message(a,b)) #define UPDATE_MSG_ID(a, b, c, d, e, f) (odbc_update_msg_id((a), (b), (c))) #else #ifdef IMAP_STORAGE @@ -997,6 +1004,8 @@ static char odbc_table[80] = "voicemessages"; #define DELETE(a,b,c,d) (vm_imap_delete(a,b,d)) #define UPDATE_MSG_ID(a, b, c, d, e, f) (vm_imap_update_msg_id((a), (b), (c), (d), (e), (f))) #else +#define COUNT(a, b) count_messages(a,b) +#define LAST_MSG_INDEX(a) last_message_index(a) #define RETRIEVE(a,b,c,d) #define DISPOSE(a,b) #define STORE(a,b,c,d,e,f,g,h,i,j,k) @@ -1322,6 +1331,136 @@ static char *strip_control_and_high(const char *input, char *buf, size_t buflen) return buf; } +/* + * These macros are currently only used by the ODBC code but + * should be used anyplace we're allocating a PATH_MAX + * sized buffer for something which will be much smaller + * in practice. + */ +#ifdef ODBC_STORAGE +/*! + * \internal + * \brief Get the length needed for a message path base. + * + * \param dir The absolute path to a directory + * + * \note The directory provided should include all components + * down to the folder level. For example: + * /var/spool/asterisk/voicemail/default/1234/INBOX + * + * \returns Number of bytes needed for the message path base. + */ +static size_t get_msg_path_len(const char *dir) +{ + if (ast_strlen_zero(dir)) { + return 0; + } + /* dir + '/' + MSGFILE_LEN + '\0' */ + return strlen(dir) + 1 + MSGFILE_LEN + 1; +} + +/* + * The longest sound file extension we currently + * have is "siren14" which is 7 characters long + * but we'll make this 12 to be extra safe. + */ +#define MAX_SOUND_EXTEN_LEN 12 +/*! + * \internal + * \brief Get the length needed for a message sound or metadata file path. + * + * \param dir The absolute path to a directory + * + * \note The directory provided should include all components + * down to the folder level. For example: + * /var/spool/asterisk/voicemail/default/1234/INBOX + * + * \returns Number of bytes needed for the message sound or metadata file path. + */ +static size_t get_msg_path_ext_len(const char *dir) +{ + if (ast_strlen_zero(dir)) { + return 0; + } + /* dir + '/' + MSGFILE_LEN + extlen(including '.') + '\0' */ + return strlen(dir) + 1 + MSGFILE_LEN + MAX_SOUND_EXTEN_LEN + 1; +} + +/*! + * \internal + * \brief Allocate a buffer on the stack containing a message file path base. + * + * \param dir The absolute path to a directory + * \param msgnum The message number or -1 for a prompt file + * + * \note The returned buffer will automatically be freed when it + * goes out of scope. + * + * If passed (/var/spool/asterisk/voicemail/default/1234/INBOX, 0) + * the returned path would be: + * /var/spool/asterisk/voicemail/default/1234/INBOX/msg0000 + * + * If passed (/var/spool/asterisk/voicemail/default/1234/unavail, -1) + * the returned path would be: + * /var/spool/asterisk/voicemail/default/1234/unavail + * (no change) + * + * \returns A pointer to the buffer containing the path. + */ +#define MAKE_FILE_PTRA(dir, msgnum) \ +({ \ + size_t __len = get_msg_path_len(dir); \ + char *__var; \ + if (msgnum < 0) { \ + __var = ast_strdupa(dir); \ + } else { \ + __var = ast_alloca(__len); \ + snprintf(__var, __len, "%s/msg%04d", dir, msgnum); \ + } \ + __var; \ +}) + +/*! + * \internal + * \brief Allocate a buffer on the stack for a message sound or metadata file path. + * + * \param dir The absolute path to a directory + * \param msgnum The message number or -1 for a prompt file + * + * \note The returned buffer will automatically be freed when it + * goes out of scope. + * + * If passed (/var/spool/asterisk/voicemail/default/1234/INBOX, 0, "txt") + * the returned path would be: + * /var/spool/asterisk/voicemail/default/1234/INBOX/msg0000.txt + * + * If passed (/var/spool/asterisk/voicemail/default/1234/unavail, -1, "WAV") + * the returned path would be: + * /var/spool/asterisk/voicemail/default/1234/unavail.WAV + * + * The buffer returned has enough space that you can safely re-use it + * for other sound file extensions. For instance: + * + * char *fn = MAKE_FILE_PTRA(dir, msgnum); + * char *full_fn = MAKE_FILE_EXT_PTRA(dir, msgnum, "txt"); + * char *fmt = "g722"; + * ...do domething with full_fn then re-use it... + * sprintf(full_fn, "%s.%s", fn, fmt); * Safe since the same dir and msgnum were used * + * + * \returns A pointer to the allocated buffer + */ +#define MAKE_FILE_EXT_PTRA(dir, msgnum, ext) \ +({ \ + size_t __len = get_msg_path_ext_len(dir); \ + char *__var = ast_alloca(__len); \ + if (msgnum < 0) { \ + snprintf(__var, __len, "%s.%s", dir, ext); \ + } else { \ + snprintf(__var, __len, "%s/msg%04d.%s", dir, msgnum, ext); \ + } \ + __var; \ +}) +#endif /*! * \brief Sets default voicemail system options to a voicemail user. @@ -3887,6 +4026,43 @@ static int msg_id_incrementor; static void generate_msg_id(char *dst); #ifdef ODBC_STORAGE + +/*! + * \internal + * \brief Create a buffer containing the SQL statement with the table name inserted. + * + * \param __sql_fmt The SQL statement with a single '%s' where the table name should be inserted. + * + * \note The buffer is allocated on the stack and should not be freed. + * + * \return A pointer to a buffer containing the SQL statement with the table name inserted. + */ +#define MAKE_SQL_PTRA(__sql_fmt) \ +({ \ + /* The NULL terminator is included in odbc_table_len. */ \ + char *__sql = ast_alloca(strlen(__sql_fmt) + odbc_table_len); \ + sprintf(__sql, __sql_fmt, odbc_table); /* Safe */ \ + __sql; \ +}) + +/*! + * \internal + * \brief Create a buffer containing the SQL statement with the table name inserted twice. + * + * \param __sql_fmt The SQL statement with two '%s' where the table name should be inserted. + * + * \note The buffer is allocated on the stack and should not be freed. + * + * \return A pointer to a buffer containing the SQL statement with the table name inserted. + */ +#define MAKE_SQL_PTRA2(__sql_fmt) \ +({ \ + /* The NULL terminator is included in odbc_table_len. */ \ + char *__sql = ast_alloca(strlen(__sql_fmt) + (odbc_table_len * 2)); \ + sprintf(__sql, __sql_fmt, odbc_table, odbc_table); /* Safe */ \ + __sql; \ +}) + struct generic_prepare_struct { char *sql; int argc; @@ -3919,20 +4095,19 @@ static SQLHSTMT generic_prepare(struct odbc_obj *obj, void *data) static void odbc_update_msg_id(char *dir, int msg_num, char *msg_id) { SQLHSTMT stmt; - char sql[PATH_MAX]; + char *sql = MAKE_SQL_PTRA("UPDATE %s SET msg_id=? WHERE dir=? AND msgnum=?"); struct odbc_obj *obj; char msg_num_str[20]; char *argv[] = { msg_id, dir, msg_num_str }; struct generic_prepare_struct gps = { .sql = sql, .argc = 3, .argv = argv }; + SCOPE_ENTER(3, "dir: %s msg_num: %d msg_id: %s\n", dir, msg_num, msg_id); obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(LOG_WARNING, "Unable to update message ID for message %d in %s\n", msg_num, dir); - return; + SCOPE_EXIT_LOG_RTN(LOG_WARNING, "Unable to update message ID for message %d in %s\n", msg_num, dir); } snprintf(msg_num_str, sizeof(msg_num_str), "%d", msg_num); - snprintf(sql, sizeof(sql), "UPDATE %s SET msg_id=? WHERE dir=? AND msgnum=?", odbc_table); stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, &gps); if (!stmt) { ast_log(LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); @@ -3940,9 +4115,60 @@ static void odbc_update_msg_id(char *dir, int msg_num, char *msg_id) SQLFreeHandle(SQL_HANDLE_STMT, stmt); } ast_odbc_release_obj(obj); - return; + SCOPE_EXIT_RTN(); +} + +#define AUDIO_ON_DISK_MAGIC "AUDMAGIC" +#define AUDIO_ON_DISK_MAGIC_LEN 8 + +static void odbc_update_set_audmagic(char *dir, int msg_num) +{ + SQLHSTMT stmt; + char *sql = MAKE_SQL_PTRA("UPDATE %s SET recording=? WHERE dir=? AND msgnum=?"); + struct odbc_obj *obj; + SQLLEN datalen = AUDIO_ON_DISK_MAGIC_LEN; + SQLLEN indlen = datalen; + int res; + char msg_num_str[20]; + SCOPE_ENTER(3, "dir: %s msg_num: %d\n", dir, msg_num); + + obj = ast_odbc_request_obj(odbc_database, 0); + if (!obj) { + SCOPE_EXIT_LOG_RTN(LOG_WARNING, "Unable to request obj for message %d in %s\n", msg_num, dir); + } + + res = SQLAllocHandle(SQL_HANDLE_STMT, obj->con, &stmt); + if (!SQL_SUCCEEDED(res)) { + ast_odbc_release_obj(obj); + SCOPE_EXIT_LOG_RTN(LOG_WARNING, "Unable to allocate stmt for message %d in %s\n", msg_num, dir); + } + + snprintf(msg_num_str, sizeof(msg_num_str), "%d", msg_num); + + SQLBindParameter(stmt, 1, SQL_PARAM_INPUT, SQL_C_BINARY, SQL_LONGVARBINARY, + datalen, 0, (void *) AUDIO_ON_DISK_MAGIC, + datalen, &indlen); + + SQLBindParameter(stmt, 2, SQL_PARAM_INPUT, SQL_C_CHAR, SQL_CHAR, + strlen(dir), 0, (void *) dir, 0, NULL); + + SQLBindParameter(stmt, 3, SQL_PARAM_INPUT, SQL_C_CHAR, SQL_CHAR, + strlen(msg_num_str), 0, (void *) msg_num_str, 0, NULL); + + res = ast_odbc_execute_sql(obj, stmt, sql); + if (!SQL_SUCCEEDED(res)) { + ast_log(LOG_WARNING, "Unable to execute stmt for message %d in %s\n", msg_num, dir); + ast_odbc_print_errors(SQL_HANDLE_STMT, stmt, "SQL Execute"); + } + SQLFreeHandle(SQL_HANDLE_STMT, stmt); + stmt = NULL; + + ast_odbc_release_obj(obj); + SCOPE_EXIT_RTN("Done\n"); } +static int odbc_store_message(const char *dir, const char *mailboxuser, const char *mailboxcontext, int msgnum); + /*! * \brief Retrieves a file from an ODBC data store. * \param dir the path to the file to be retrieved. @@ -3957,7 +4183,7 @@ static void odbc_update_msg_id(char *dir, int msg_num, char *msg_id) * * \return 0 on success, -1 on error. */ -static int retrieve_file(char *dir, int msgnum) +static int odbc_retrieve_message(char *dir, int msgnum) { int x = 0; int res; @@ -3966,7 +4192,7 @@ static int retrieve_file(char *dir, int msgnum) void *fdm = MAP_FAILED; SQLSMALLINT colcount = 0; SQLHSTMT stmt; - char sql[PATH_MAX]; + char *sql = MAKE_SQL_PTRA("SELECT * FROM %s WHERE dir=? AND msgnum=?"); char fmt[80] = ""; char *c; char coltitle[256]; @@ -3978,18 +4204,22 @@ static int retrieve_file(char *dir, int msgnum) SQLLEN colsize2; FILE *f = NULL; char rowdata[80]; - char fn[PATH_MAX]; - char full_fn[PATH_MAX]; + char *fn = MAKE_FILE_PTRA(dir, msgnum); + char *full_fn = MAKE_FILE_EXT_PTRA(dir, msgnum, "txt"); char msgnums[80]; + char *mailboxuser = NULL; + char *mailboxcontext = NULL; char msg_id[MSG_ID_LEN] = ""; char *argv[] = { dir, msgnums }; struct generic_prepare_struct gps = { .sql = sql, .argc = 2, .argv = argv }; struct odbc_obj *obj; + int storage_conversion_to_disk = 0; + int storage_conversion_to_odbc = 0; + SCOPE_ENTER(3, "dir: %s msgnum: %d msgtype: %s\n", dir, msgnum, msgnum < 0 ? "Greeting" : "Message"); obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return -1; + SCOPE_EXIT_LOG_RTN_VALUE(-1, AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } ast_copy_string(fmt, vmfmts, sizeof(fmt)); @@ -4000,21 +4230,14 @@ static int retrieve_file(char *dir, int msgnum) strcpy(fmt, "WAV"); snprintf(msgnums, sizeof(msgnums), "%d", msgnum); - if (msgnum > -1) - make_file(fn, sizeof(fn), dir, msgnum); - else - ast_copy_string(fn, dir, sizeof(fn)); - - /* Create the information file */ - snprintf(full_fn, sizeof(full_fn), "%s.txt", fn); + ast_trace(-1, "Opening '%s' for writing\n", full_fn); if (!(f = fopen(full_fn, "w+"))) { ast_log(AST_LOG_WARNING, "Failed to open/create '%s'\n", full_fn); goto bail; } - snprintf(full_fn, sizeof(full_fn), "%s.%s", fn, fmt); - snprintf(sql, sizeof(sql), "SELECT * FROM %s WHERE dir=? AND msgnum=?", odbc_table); + sprintf(full_fn, "%s.%s", fn, fmt); /* Safe. We're just replacing the file exten. */ stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, &gps); if (!stmt) { @@ -4030,12 +4253,6 @@ static int retrieve_file(char *dir, int msgnum) goto bail_with_handle; } - fd = open(full_fn, O_RDWR | O_CREAT | O_TRUNC, VOICEMAIL_FILE_MODE); - if (fd < 0) { - ast_log(AST_LOG_WARNING, "Failed to write '%s': %s\n", full_fn, strerror(errno)); - goto bail_with_handle; - } - res = SQLNumResultCols(stmt, &colcount); if (!SQL_SUCCEEDED(res)) { ast_log(AST_LOG_WARNING, "SQL Column Count error!\n[%s]\n\n", sql); @@ -4053,46 +4270,81 @@ static int retrieve_file(char *dir, int msgnum) ast_log(AST_LOG_WARNING, "SQL Describe Column error!\n[%s]\n\n", sql); goto bail_with_handle; } + if (!strcasecmp(coltitle, "recording")) { off_t offset; + char tmp[1] = ""; + res = SQLGetData(stmt, x + 1, SQL_BINARY, rowdata, 0, &colsize2); fdlen = colsize2; - if (fd > -1) { - char tmp[1] = ""; - lseek(fd, fdlen - 1, SEEK_SET); - if (write(fd, tmp, 1) != 1) { - close(fd); - fd = -1; - continue; + ast_trace(-1, "Audio size: %ld\n", colsize2); + if (colsize2 == AUDIO_ON_DISK_MAGIC_LEN) { + res = SQLGetData(stmt, x + 1, SQL_BINARY, rowdata, AUDIO_ON_DISK_MAGIC_LEN, NULL); + if (memcmp(rowdata, AUDIO_ON_DISK_MAGIC, AUDIO_ON_DISK_MAGIC_LEN) != 0) { + ast_log(AST_LOG_WARNING, "Invalid audio magic number '0x%02X%02X%02X%02X%02X%02X%02X%02X' for '%s'\n", + rowdata[0], rowdata[1], rowdata[2], rowdata[3], rowdata[4], rowdata[5], rowdata[6], + rowdata[7], full_fn); + goto bail_with_handle; } - /* Read out in small chunks */ - for (offset = 0; offset < colsize2; offset += CHUNKSIZE) { - if ((fdm = mmap(NULL, CHUNKSIZE, PROT_READ | PROT_WRITE, MAP_SHARED, fd, offset)) == MAP_FAILED) { - ast_log(AST_LOG_WARNING, "Could not mmap the output file: %s (%d)\n", strerror(errno), errno); - goto bail_with_handle; - } - res = SQLGetData(stmt, x + 1, SQL_BINARY, fdm, CHUNKSIZE, NULL); - munmap(fdm, CHUNKSIZE); - if (!SQL_SUCCEEDED(res)) { - ast_log(AST_LOG_WARNING, "SQL Get Data error!\n[%s]\n\n", sql); - unlink(full_fn); - goto bail_with_handle; - } + ast_trace(-1, "Audio is stored on disk. No need to write '%s'\n", full_fn); + if (!ast_test_flag((&globalflags), VM_ODBC_AUDIO_ON_DISK)) { + storage_conversion_to_odbc = 1; } - if (truncate(full_fn, fdlen) < 0) { - ast_log(LOG_WARNING, "Unable to truncate '%s': %s\n", full_fn, strerror(errno)); + + continue; + } + + ast_trace(-1, "Opening '%s' for writing\n", full_fn); + fd = open(full_fn, O_RDWR | O_CREAT | O_TRUNC, VOICEMAIL_FILE_MODE); + if (fd < 0) { + ast_log(AST_LOG_WARNING, "Failed to open '%s' for writing: %s\n", full_fn, strerror(errno)); + goto bail_with_handle; + } + if (ast_test_flag((&globalflags), VM_ODBC_AUDIO_ON_DISK)) { + storage_conversion_to_disk = 1; + } + + lseek(fd, fdlen - 1, SEEK_SET); + if (write(fd, tmp, 1) != 1) { + close(fd); + fd = -1; + continue; + } + /* Read out in small chunks */ + for (offset = 0; offset < colsize2; offset += CHUNKSIZE) { + if ((fdm = mmap(NULL, CHUNKSIZE, PROT_READ | PROT_WRITE, MAP_SHARED, fd, offset)) == MAP_FAILED) { + ast_log(AST_LOG_WARNING, "Could not mmap the output file: %s (%d)\n", strerror(errno), errno); + goto bail_with_handle; } + res = SQLGetData(stmt, x + 1, SQL_BINARY, fdm, CHUNKSIZE, NULL); + munmap(fdm, CHUNKSIZE); + if (!SQL_SUCCEEDED(res)) { + ast_log(AST_LOG_WARNING, "SQL Get Data error!\n[%s]\n\n", sql); + unlink(full_fn); + goto bail_with_handle; + } + } + if (truncate(full_fn, fdlen) < 0) { + ast_log(LOG_WARNING, "Unable to truncate '%s': %s\n", full_fn, strerror(errno)); } + ast_trace(-1, "Wrote %d bytes to '%s'\n", (int)fdlen, full_fn); } else { res = SQLGetData(stmt, x + 1, SQL_CHAR, rowdata, sizeof(rowdata), NULL); if (res == SQL_NULL_DATA && !strcasecmp(coltitle, "msg_id")) { - /* Generate msg_id now, but don't store it until we're done with this - connection */ + /* + * Generate msg_id if there wasn't one, but don't store it until we're + * done with this connection. + */ generate_msg_id(msg_id); + ast_trace(-1, "msg_id was NULL. Generating new one: %s\n", msg_id); snprintf(rowdata, sizeof(rowdata), "%s", msg_id); + } else if (!strcasecmp(coltitle, "mailboxuser")) { + mailboxuser = ast_strdupa(rowdata); + } else if (!strcasecmp(coltitle, "mailboxcontext")) { + mailboxcontext = ast_strdupa(rowdata); } else if (res == SQL_NULL_DATA && !strcasecmp(coltitle, "category")) { /* Ignore null column value for category */ - ast_debug(3, "Ignoring null category column in ODBC voicemail retrieve_file.\n"); + ast_trace(-1, "Ignoring null category column in ODBC voicemail retrieve_file.\n"); continue; } else if (!SQL_SUCCEEDED(res)) { ast_log(AST_LOG_WARNING, "SQL Get Data error! coltitle=%s\n[%s]\n\n", coltitle, sql); @@ -4122,7 +4374,27 @@ static int retrieve_file(char *dir, int msgnum) odbc_update_msg_id(dir, msgnum, msg_id); } - return x - 1; + if (SQL_SUCCEEDED(res)) { + if (storage_conversion_to_disk) { + /* + * If we're currently storing audio on disk but there was pre-existing + * audio in the database, we need to update the database to set the + * 'recording' column to AUDIO_ON_DISK_MAGIC. + */ + SCOPE_CALL(-1, odbc_update_set_audmagic, dir, msgnum); + } + if (storage_conversion_to_odbc) { + /* + * If we're currently storing audio in the database but there was + * pre-existing audio on disk, we need to add the audio back + * into the database overwriting the AUDIO_ON_DISK_MAGIC + * magic number. + */ + SCOPE_CALL(-1, odbc_store_message, dir, mailboxuser, mailboxcontext, msgnum); + } + } + + SCOPE_EXIT_RTN_VALUE(x - 1, "Done. msg_id: %s RC: %d\n", msg_id, x - 1); } /*! @@ -4134,25 +4406,23 @@ static int retrieve_file(char *dir, int msgnum) * * \return the value of zero or greater to indicate the last message index in use, -1 to indicate none. */ -static int last_message_index(char *dir) +static int odbc_last_message_index(char *dir) { int x = -1; int res; SQLHSTMT stmt; - char sql[PATH_MAX]; + char *sql = MAKE_SQL_PTRA("SELECT msgnum FROM %s WHERE dir=? order by msgnum desc"); char rowdata[20]; char *argv[] = { dir }; struct generic_prepare_struct gps = { .sql = sql, .argc = 1, .argv = argv }; struct odbc_obj *obj; + SCOPE_ENTER(3, "dir: %s\n", dir); obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return -1; + SCOPE_EXIT_LOG_RTN_VALUE(-1, AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } - snprintf(sql, sizeof(sql), "SELECT msgnum FROM %s WHERE dir=? order by msgnum desc", odbc_table); - stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, &gps); if (!stmt) { ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); @@ -4162,7 +4432,7 @@ static int last_message_index(char *dir) res = SQLFetch(stmt); if (!SQL_SUCCEEDED(res)) { if (res == SQL_NO_DATA) { - ast_log(AST_LOG_DEBUG, "Directory '%s' has no messages and therefore no index was retrieved.\n", dir); + ast_trace(-1, "Directory '%s' has no messages and therefore no index was retrieved.\n", dir); } else { ast_log(AST_LOG_WARNING, "SQL Fetch error!\n[%s]\n\n", sql); } @@ -4185,7 +4455,7 @@ static int last_message_index(char *dir) bail: ast_odbc_release_obj(obj); - return x; + SCOPE_EXIT_RTN_VALUE(x, "Done. Last message index: %d\n", x); } /*! @@ -4197,26 +4467,25 @@ static int last_message_index(char *dir) * * \return greater than zero if the message exists, zero when the message does not exist or on error. */ -static int message_exists(char *dir, int msgnum) +static int odbc_message_exists(char *dir, int msgnum) { int x = 0; int res; SQLHSTMT stmt; - char sql[PATH_MAX]; + char *sql = MAKE_SQL_PTRA("SELECT COUNT(*) FROM %s WHERE dir=? AND msgnum=?"); char rowdata[20]; char msgnums[20]; char *argv[] = { dir, msgnums }; struct generic_prepare_struct gps = { .sql = sql, .argc = 2, .argv = argv }; struct odbc_obj *obj; + SCOPE_ENTER(3, "dir: %s msgnum: %d\n", dir, msgnum); obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return 0; + SCOPE_EXIT_LOG_RTN_VALUE(0, AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } snprintf(msgnums, sizeof(msgnums), "%d", msgnum); - snprintf(sql, sizeof(sql), "SELECT COUNT(*) FROM %s WHERE dir=? AND msgnum=?", odbc_table); stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, &gps); if (!stmt) { ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); @@ -4244,7 +4513,7 @@ static int message_exists(char *dir, int msgnum) bail: ast_odbc_release_obj(obj); - return x; + SCOPE_EXIT_RTN_VALUE(x, "Done. Msg %s\n", x ? "exists" : "does not exist"); } /*! @@ -4256,24 +4525,23 @@ static int message_exists(char *dir, int msgnum) * * \return The count of messages being zero or more, less than zero on error. */ -static int count_messages(struct ast_vm_user *vmu, char *dir) +static int odbc_count_messages(struct ast_vm_user *vmu, char *dir) { int x = -1; int res; SQLHSTMT stmt; - char sql[PATH_MAX]; + char *sql = MAKE_SQL_PTRA("SELECT COUNT(*) FROM %s WHERE dir=?"); char rowdata[20]; char *argv[] = { dir }; struct generic_prepare_struct gps = { .sql = sql, .argc = 1, .argv = argv }; struct odbc_obj *obj; + SCOPE_ENTER(3, "dir: %s\n", dir); obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return -1; + SCOPE_EXIT_LOG_RTN_VALUE(-1, AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } - snprintf(sql, sizeof(sql), "SELECT COUNT(*) FROM %s WHERE dir=?", odbc_table); stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, &gps); if (!stmt) { ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); @@ -4301,7 +4569,7 @@ static int count_messages(struct ast_vm_user *vmu, char *dir) bail: ast_odbc_release_obj(obj); - return x; + SCOPE_EXIT_RTN_VALUE(x, "Done. Count %d\n", x); } /*! @@ -4312,25 +4580,25 @@ static int count_messages(struct ast_vm_user *vmu, char *dir) * This method is used when mailboxes are stored in an ODBC back end. * The specified message is directly deleted from the database 'voicemessages' table. */ -static void delete_file(const char *sdir, int smsg) +#define DELETE_SQL_FMT "DELETE FROM %s WHERE dir=? AND msgnum=?" +static void odbc_delete_message(const char *sdir, int smsg) { SQLHSTMT stmt; - char sql[PATH_MAX]; + char *sql = MAKE_SQL_PTRA(DELETE_SQL_FMT); char msgnums[20]; char *argv[] = { NULL, msgnums }; struct generic_prepare_struct gps = { .sql = sql, .argc = 2, .argv = argv }; struct odbc_obj *obj; + SCOPE_ENTER(3, "sdir: %s smsg: %d\n", sdir, smsg); obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return; + SCOPE_EXIT_LOG_RTN(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } argv[0] = ast_strdupa(sdir); snprintf(msgnums, sizeof(msgnums), "%d", smsg); - snprintf(sql, sizeof(sql), "DELETE FROM %s WHERE dir=? AND msgnum=?", odbc_table); stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, &gps); if (!stmt) { ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); @@ -4339,7 +4607,13 @@ static void delete_file(const char *sdir, int smsg) } ast_odbc_release_obj(obj); - return; + if (ast_test_flag((&globalflags), VM_ODBC_AUDIO_ON_DISK)) { + char *src_fn = MAKE_FILE_PTRA(sdir, smsg); + ast_trace(-1, "Audio stored on disk. Deleting '%s'\n", src_fn); + ast_filedelete(src_fn, NULL); + } + + SCOPE_EXIT_RTN("Done\n"); } /*! @@ -4353,28 +4627,32 @@ static void delete_file(const char *sdir, int smsg) * * This method is used for the COPY macro when mailboxes are stored in an ODBC back end. */ -static void copy_file(char *sdir, int smsg, char *ddir, int dmsg, char *dmailboxuser, char *dmailboxcontext) +#define COPY_SQL_FMT "INSERT INTO %s (dir, msgnum, msg_id, context, macrocontext, callerid, origtime, " \ + "duration, recording, flag, mailboxuser, mailboxcontext) " \ + "SELECT ?,?,msg_id,context,macrocontext,callerid,origtime,duration,recording,flag,?,? " \ + "FROM %s WHERE dir=? AND msgnum=?" +static void odbc_copy_message(char *sdir, int smsg, char *ddir, int dmsg, char *dmailboxuser, char *dmailboxcontext) { SQLHSTMT stmt; - char sql[512]; + char *sql = MAKE_SQL_PTRA2(COPY_SQL_FMT); char msgnums[20]; char msgnumd[20]; - char msg_id[MSG_ID_LEN]; struct odbc_obj *obj; - char *argv[] = { ddir, msgnumd, msg_id, dmailboxuser, dmailboxcontext, sdir, msgnums }; - struct generic_prepare_struct gps = { .sql = sql, .argc = 7, .argv = argv }; + char *argv[] = { ddir, msgnumd, dmailboxuser, dmailboxcontext, sdir, msgnums }; + struct generic_prepare_struct gps = { .sql = sql, .argc = 6, .argv = argv }; + SCOPE_ENTER(3, "sdir: %s smsg: %d duser: %s dcontext: %s ddir: %s dmsg: %d\n", + sdir, smsg, dmailboxuser, dmailboxcontext, ddir, dmsg); + + SCOPE_CALL(-1, odbc_delete_message, ddir, dmsg); - generate_msg_id(msg_id); - delete_file(ddir, dmsg); obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return; + SCOPE_EXIT_LOG_RTN(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } snprintf(msgnums, sizeof(msgnums), "%d", smsg); snprintf(msgnumd, sizeof(msgnumd), "%d", dmsg); - snprintf(sql, sizeof(sql), "INSERT INTO %s (dir, msgnum, msg_id, context, macrocontext, callerid, origtime, duration, recording, flag, mailboxuser, mailboxcontext) SELECT ?,?,?,context,macrocontext,callerid,origtime,duration,recording,flag,?,? FROM %s WHERE dir=? AND msgnum=?", odbc_table, odbc_table); + stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, &gps); if (!stmt) ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s] (You probably don't have MySQL 4.1 or later installed)\n\n", sql); @@ -4382,11 +4660,19 @@ static void copy_file(char *sdir, int smsg, char *ddir, int dmsg, char *dmailbox SQLFreeHandle(SQL_HANDLE_STMT, stmt); ast_odbc_release_obj(obj); - return; + if (ast_test_flag((&globalflags), VM_ODBC_AUDIO_ON_DISK)) { + char *src_fn = MAKE_FILE_PTRA(sdir, smsg); + char *dst_fn = MAKE_FILE_PTRA(ddir, dmsg); + + ast_trace(-1, "Audio stored on disk. Copying '%s' to '%s'\n", src_fn, dst_fn); + ast_filecopy(src_fn, dst_fn, NULL); + } + + SCOPE_EXIT_RTN("Done\n"); } +#undef COPY_SQL_FMT struct insert_data { - char *sql; const char *dir; const char *msgnums; void *data; @@ -4404,16 +4690,44 @@ struct insert_data { const char *msg_id; }; -static SQLHSTMT insert_data_cb(struct odbc_obj *obj, void *vdata) +#define STORE_SQL_FMT_CAT "INSERT INTO %s (dir, msgnum, recording, context, macrocontext, callerid, " \ + "origtime, duration, mailboxuser, mailboxcontext, flag, msg_id, category) " \ + "VALUES (?,?,?,?,?,?,?,?,?,?,?,?)" +#define STORE_SQL_FMT "INSERT INTO %s (dir, msgnum, recording, context, macrocontext, callerid, "\ + "origtime, duration, mailboxuser, mailboxcontext, flag, msg_id) "\ + "VALUES (?,?,?,?,?,?,?,?,?,?,?)" + +static SQLHSTMT odbc_insert_data_cb(struct odbc_obj *obj, void *vdata) { struct insert_data *data = vdata; + char *insert_sql; + char *delete_sql; int res; SQLHSTMT stmt; + SCOPE_ENTER(3, "dir: %s msgnums: %s msg_id: %s\n", data->dir, data->msgnums, + data->msg_id); res = SQLAllocHandle(SQL_HANDLE_STMT, obj->con, &stmt); if (!SQL_SUCCEEDED(res)) { - ast_log(AST_LOG_WARNING, "SQL Alloc Handle failed!\n"); - return NULL; + SCOPE_EXIT_LOG_RTN_VALUE(NULL, AST_LOG_WARNING, "SQL Alloc Handle failed!\n"); + } + + /* Delete any existing row with the same dir and msgnum */ + delete_sql = MAKE_SQL_PTRA(DELETE_SQL_FMT); + SQLBindParameter(stmt, 1, SQL_PARAM_INPUT, SQL_C_CHAR, SQL_CHAR, strlen(data->dir), 0, (void *) data->dir, 0, NULL); + SQLBindParameter(stmt, 2, SQL_PARAM_INPUT, SQL_C_CHAR, SQL_CHAR, strlen(data->msgnums), 0, (void *) data->msgnums, 0, NULL); + res = ast_odbc_execute_sql(obj, stmt, delete_sql); + if (!SQL_SUCCEEDED(res)) { + ast_trace(-1, "There wasn't an existing row. Good.\n"); + } else { + ast_trace(-1, "There WAS an existing row. This is OK if we're replacing a message.\n"); + } + SQLFreeHandle(SQL_HANDLE_STMT, stmt); + stmt = NULL; + + res = SQLAllocHandle(SQL_HANDLE_STMT, obj->con, &stmt); + if (!SQL_SUCCEEDED(res)) { + SCOPE_EXIT_LOG_RTN_VALUE(NULL, AST_LOG_WARNING, "SQL Alloc Handle failed!\n"); } SQLBindParameter(stmt, 1, SQL_PARAM_INPUT, SQL_C_CHAR, SQL_CHAR, strlen(data->dir), 0, (void *) data->dir, 0, NULL); @@ -4429,16 +4743,20 @@ static SQLHSTMT insert_data_cb(struct odbc_obj *obj, void *vdata) SQLBindParameter(stmt, 11, SQL_PARAM_INPUT, SQL_C_CHAR, SQL_CHAR, strlen(data->flag), 0, (void *) data->flag, 0, NULL); SQLBindParameter(stmt, 12, SQL_PARAM_INPUT, SQL_C_CHAR, SQL_CHAR, strlen(data->msg_id), 0, (void *) data->msg_id, 0, NULL); if (!ast_strlen_zero(data->category)) { + insert_sql = MAKE_SQL_PTRA(STORE_SQL_FMT_CAT); SQLBindParameter(stmt, 13, SQL_PARAM_INPUT, SQL_C_CHAR, SQL_CHAR, strlen(data->category), 0, (void *) data->category, 0, NULL); + } else { + insert_sql = MAKE_SQL_PTRA(STORE_SQL_FMT); } - res = ast_odbc_execute_sql(obj, stmt, data->sql); + res = ast_odbc_execute_sql(obj, stmt, insert_sql); if (!SQL_SUCCEEDED(res)) { - ast_log(AST_LOG_WARNING, "SQL Direct Execute failed!\n"); + ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s]\n", insert_sql); + ast_odbc_print_errors(SQL_HANDLE_STMT, stmt, "SQL Execute"); SQLFreeHandle(SQL_HANDLE_STMT, stmt); - return NULL; + stmt = NULL; } - return stmt; + SCOPE_EXIT_RTN_VALUE(stmt, "%s\n", stmt ? "Success" : "Failed"); } /*! @@ -4454,31 +4772,29 @@ static SQLHSTMT insert_data_cb(struct odbc_obj *obj, void *vdata) * * \return the zero on success -1 on error. */ -static int store_file(const char *dir, const char *mailboxuser, const char *mailboxcontext, int msgnum) +static int odbc_store_message(const char *dir, const char *mailboxuser, const char *mailboxcontext, int msgnum) { int res = 0; int fd = -1; void *fdm = MAP_FAILED; off_t fdlen = -1; SQLHSTMT stmt; - char sql[PATH_MAX]; char msgnums[20]; - char fn[PATH_MAX]; - char full_fn[PATH_MAX]; + char *fn = MAKE_FILE_PTRA(dir, msgnum); + char *full_fn = MAKE_FILE_EXT_PTRA(dir, msgnum, "txt"); char fmt[80]=""; char *c; struct ast_config *cfg = NULL; struct odbc_obj *obj; - struct insert_data idata = { .sql = sql, .msgnums = msgnums, .dir = dir, .mailboxuser = mailboxuser, .mailboxcontext = mailboxcontext, + struct insert_data idata = { .msgnums = msgnums, .dir = dir, .mailboxuser = mailboxuser, .mailboxcontext = mailboxcontext, .context = "", .macrocontext = "", .callerid = "", .origtime = "", .duration = "", .category = "", .flag = "", .msg_id = "" }; struct ast_flags config_flags = { CONFIG_FLAG_NOCACHE }; - - delete_file(dir, msgnum); + SCOPE_ENTER(3, "dir: %s user: %s context: %s msgnum: %d msgtype: %s\n", + dir, mailboxuser, mailboxcontext, msgnum, msgnum < 0 ? "Greeting" : "Message"); obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return -1; + SCOPE_EXIT_LOG_RTN_VALUE(-1, AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } do { @@ -4488,21 +4804,38 @@ static int store_file(const char *dir, const char *mailboxuser, const char *mail *c = '\0'; if (!strcasecmp(fmt, "wav49")) strcpy(fmt, "WAV"); + + ast_trace(-1, "Formats: %s Using format: '%s'\n", vmfmts, fmt); snprintf(msgnums, sizeof(msgnums), "%d", msgnum); - if (msgnum > -1) - make_file(fn, sizeof(fn), dir, msgnum); - else - ast_copy_string(fn, dir, sizeof(fn)); - snprintf(full_fn, sizeof(full_fn), "%s.txt", fn); + + ast_trace(-1, "Base path: '%s'\n", fn); + ast_trace(-1, "Opening '%s'\n", full_fn); cfg = ast_config_load(full_fn, config_flags); - snprintf(full_fn, sizeof(full_fn), "%s.%s", fn, fmt); - fd = open(full_fn, O_RDWR); - if (fd < 0) { - ast_log(AST_LOG_WARNING, "Open of sound file '%s' failed: %s\n", full_fn, strerror(errno)); - res = -1; - break; + if (!valid_config(cfg)) { + if (msgnum < 0) { + ast_trace(-1, "No information file found for '%s'. This is a greeting so this is OK.\n", full_fn); + } else { + ast_log(AST_LOG_WARNING, "Failed to open '%s'\n", full_fn); + res = -1; + break; + } + } + + sprintf(full_fn, "%s.%s", fn, fmt); /* Safe */ + if (ast_test_flag((&globalflags), VM_ODBC_AUDIO_ON_DISK)) { + ast_trace(-1, "Audio stored on disk. No need to open '%s'\n", full_fn); + } else { + ast_trace(-1, "Opening '%s'\n", full_fn); + fd = open(full_fn, O_RDWR); + if (fd < 0) { + ast_log(AST_LOG_WARNING, "Open of sound file '%s' failed: %s\n", full_fn, strerror(errno)); + res = -1; + break; + } } + if (valid_config(cfg)) { + ast_trace(-1, "Using information file '%s'\n", fn); if (!(idata.context = ast_variable_retrieve(cfg, "message", "context"))) { idata.context = ""; } @@ -4528,25 +4861,28 @@ static int store_file(const char *dir, const char *mailboxuser, const char *mail idata.msg_id = ""; } } - fdlen = lseek(fd, 0, SEEK_END); - if (fdlen < 0 || lseek(fd, 0, SEEK_SET) < 0) { - ast_log(AST_LOG_WARNING, "Failed to process sound file '%s': %s\n", full_fn, strerror(errno)); - res = -1; - break; - } - fdm = mmap(NULL, fdlen, PROT_READ | PROT_WRITE, MAP_SHARED, fd, 0); - if (fdm == MAP_FAILED) { - ast_log(AST_LOG_WARNING, "Memory map failed for sound file '%s'!\n", full_fn); - res = -1; - break; - } - idata.data = fdm; - idata.datalen = idata.indlen = fdlen; - if (!ast_strlen_zero(idata.category)) - snprintf(sql, sizeof(sql), "INSERT INTO %s (dir,msgnum,recording,context,macrocontext,callerid,origtime,duration,mailboxuser,mailboxcontext,flag,msg_id,category) VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?)", odbc_table); - else - snprintf(sql, sizeof(sql), "INSERT INTO %s (dir,msgnum,recording,context,macrocontext,callerid,origtime,duration,mailboxuser,mailboxcontext,flag,msg_id) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)", odbc_table); + if (fd < 0) { + ast_trace(-1, "Audio stored on disk. Not reading sound file '%s' but setting magic number.\n", full_fn); + idata.data = AUDIO_ON_DISK_MAGIC; + idata.datalen = idata.indlen = AUDIO_ON_DISK_MAGIC_LEN; + } else { + ast_trace(-1, "Reading sound file '%s'\n", full_fn); + fdlen = lseek(fd, 0, SEEK_END); + if (fdlen < 0 || lseek(fd, 0, SEEK_SET) < 0) { + ast_log(AST_LOG_WARNING, "Failed to process sound file '%s': %s\n", full_fn, strerror(errno)); + res = -1; + break; + } + fdm = mmap(NULL, fdlen, PROT_READ | PROT_WRITE, MAP_SHARED, fd, 0); + if (fdm == MAP_FAILED) { + ast_log(AST_LOG_WARNING, "Memory map failed for sound file '%s'!\n", full_fn); + res = -1; + break; + } + idata.data = fdm; + idata.datalen = idata.indlen = fdlen; + } if (ast_strlen_zero(idata.origtime)) { idata.origtime = "0"; @@ -4556,10 +4892,9 @@ static int store_file(const char *dir, const char *mailboxuser, const char *mail idata.duration = "0"; } - if ((stmt = ast_odbc_direct_execute(obj, insert_data_cb, &idata))) { + if ((stmt = ast_odbc_direct_execute(obj, odbc_insert_data_cb, &idata))) { SQLFreeHandle(SQL_HANDLE_STMT, stmt); } else { - ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); res = -1; } } while (0); @@ -4572,8 +4907,10 @@ static int store_file(const char *dir, const char *mailboxuser, const char *mail munmap(fdm, fdlen); if (fd > -1) close(fd); - return res; + SCOPE_EXIT_RTN_VALUE(res, "%s\n", res ? "Failed" : "Success"); } +#undef STORE_SQL_FMT +#undef STORE_SQL_FMT_CAT /*! * \brief Renames a message in a mailbox folder. @@ -4588,34 +4925,44 @@ static int store_file(const char *dir, const char *mailboxuser, const char *mail * The is usually used to resequence the messages in the mailbox, such as to delete messag index 0, it would be called successively to slide all the other messages down one index. * But in theory, because the SQL query performs an update on (dir, msgnum, mailboxuser, mailboxcontext) in the database, it should be possible to have the message relocated to another mailbox or context as well. */ -static void rename_file(char *sdir, int smsg, char *mailboxuser, char *mailboxcontext, char *ddir, int dmsg) +static void odbc_rename_message(char *sdir, int smsg, char *mailboxuser, char *mailboxcontext, char *ddir, int dmsg) { SQLHSTMT stmt; - char sql[PATH_MAX]; + char *sql = MAKE_SQL_PTRA("UPDATE %s SET dir=?, msgnum=? WHERE mailboxuser=? AND mailboxcontext=? AND dir=? AND msgnum=?"); char msgnums[20]; char msgnumd[20]; struct odbc_obj *obj; char *argv[] = { ddir, msgnumd, mailboxuser, mailboxcontext, sdir, msgnums }; struct generic_prepare_struct gps = { .sql = sql, .argc = 6, .argv = argv }; + SCOPE_ENTER(3, "sdir: %s smsg: %d user: %s context: %s ddir: %s dmsg: %d\n", sdir, smsg, + mailboxuser, mailboxcontext, ddir, dmsg); - delete_file(ddir, dmsg); + SCOPE_CALL(-1, odbc_delete_message, ddir, dmsg); obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return; + SCOPE_EXIT_LOG_RTN(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } snprintf(msgnums, sizeof(msgnums), "%d", smsg); snprintf(msgnumd, sizeof(msgnumd), "%d", dmsg); - snprintf(sql, sizeof(sql), "UPDATE %s SET dir=?, msgnum=?, mailboxuser=?, mailboxcontext=? WHERE dir=? AND msgnum=?", odbc_table); + stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, &gps); if (!stmt) ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); else SQLFreeHandle(SQL_HANDLE_STMT, stmt); ast_odbc_release_obj(obj); - return; + + if (ast_test_flag((&globalflags), VM_ODBC_AUDIO_ON_DISK)) { + char *src_fn = MAKE_FILE_PTRA(sdir, smsg); + char *dst_fn = MAKE_FILE_PTRA(ddir, dmsg); + + ast_trace(-1, "Recordings stored on disk. Renaming '%s' to '%s'\n", src_fn, dst_fn); + ast_filerename(src_fn, dst_fn, NULL); + } + + SCOPE_EXIT_RTN("Done.\n"); } /*! @@ -4629,22 +4976,23 @@ static void rename_file(char *sdir, int smsg, char *mailboxuser, char *mailboxco * Note that this does not remove the message from the mailbox folders, to do that we would use delete_file(). * \return zero on success, -1 on error. */ -static int remove_file(char *dir, int msgnum) +static int odbc_remove_files(char *dir, int msgnum) { - char fn[PATH_MAX] = ""; - char full_fn[PATH_MAX + 4]; /* Plus .txt */ - char msgnums[80]; + char *fn = MAKE_FILE_PTRA(dir, msgnum); + char *full_fn = MAKE_FILE_EXT_PTRA(dir, msgnum, "txt"); + SCOPE_ENTER(3, "dir: %s msgnum: %d\n", dir, msgnum); - if (msgnum > -1) { - snprintf(msgnums, sizeof(msgnums), "%d", msgnum); - make_file(fn, sizeof(fn), dir, msgnum); + if (ast_test_flag((&globalflags), VM_ODBC_AUDIO_ON_DISK)) { + ast_trace(-1, "Audio stored on disk. Keeping '%s' sound files\n", fn); } else { - ast_copy_string(fn, dir, sizeof(fn)); + ast_trace(-1, "Audio stored in ODBC. Removing '%s' sound files\n", fn); + ast_filedelete(fn, NULL); } - ast_filedelete(fn, NULL); - snprintf(full_fn, sizeof(full_fn), "%s.txt", fn); + + /* Always remove the information file */ + ast_trace(-1, "Removing '%s' information file\n", full_fn); unlink(full_fn); - return 0; + SCOPE_EXIT_RTN_VALUE(0, "Done.\n"); } #else #ifndef IMAP_STORAGE @@ -4881,6 +5229,8 @@ static int vm_delete(char *file) { char *txt; int txtsize = 0; + int res = 0; + SCOPE_ENTER(3, "file: %s\n", file); txtsize = (strlen(file) + 5)*sizeof(char); txt = ast_alloca(txtsize); @@ -4891,8 +5241,11 @@ static int vm_delete(char *file) ast_destroy_realtime("voicemail_data", "filename", file, SENTINEL); } snprintf(txt, txtsize, "%s.txt", file); + ast_trace(-1, "unlinking '%s'\n", txt); unlink(txt); - return ast_filedelete(file, NULL); + ast_trace(-1, "deleting sound files '%s'\n", file); + res = ast_filedelete(file, NULL); + SCOPE_EXIT_RTN_VALUE(res, "Done. RC: %d\n", res); } static void prep_email_sub_vars(struct ast_channel *ast, struct ast_vm_user *vmu, int msgnum, char *context, char *mailbox, const char *fromfolder, char *cidnum, char *cidname, char *dur, char *date, const char *category, const char *flag) @@ -5776,48 +6129,49 @@ static void free_zone(struct vm_zone *z) } #ifdef ODBC_STORAGE - +#define COUNT_MSGS_SQL_FMT "SELECT COUNT(*) FROM %s WHERE dir = '%s%s/%s/%s'" static int count_messages_in_folder(struct odbc_obj *odbc, const char *context, const char *mailbox, const char *folder, int *messages) { int res; - char sql[PATH_MAX]; + char sql[sizeof(COUNT_MSGS_SQL_FMT) + odbc_table_len + strlen(VM_SPOOL_DIR) + + strlen(context) + strlen(mailbox) + strlen(folder)]; char rowdata[20]; SQLHSTMT stmt = NULL; struct generic_prepare_struct gps = { .sql = sql, .argc = 0 }; + SCOPE_ENTER(3, "context: %s mb: %s folder: %s", context, mailbox, folder); if (!messages) { - return 0; + SCOPE_EXIT_RTN_VALUE(0, "No messages pointer\n"); } - snprintf(sql, sizeof(sql), "SELECT COUNT(*) FROM %s WHERE dir = '%s%s/%s/%s'", odbc_table, VM_SPOOL_DIR, context, mailbox, folder); + snprintf(sql, sizeof(sql), COUNT_MSGS_SQL_FMT, odbc_table, VM_SPOOL_DIR, context, mailbox, folder); if (!(stmt = ast_odbc_prepare_and_execute(odbc, generic_prepare, &gps))) { - ast_log(LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); - return 1; + SCOPE_EXIT_LOG_RTN_VALUE(1, LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); } res = SQLFetch(stmt); if (!SQL_SUCCEEDED(res)) { - ast_log(LOG_WARNING, "SQL Fetch error!\n[%s]\n\n", sql); SQLFreeHandle(SQL_HANDLE_STMT, stmt); - return 1; + SCOPE_EXIT_LOG_RTN_VALUE(1, LOG_WARNING, "SQL Fetch error!\n[%s]\n\n", sql); } res = SQLGetData(stmt, 1, SQL_CHAR, rowdata, sizeof(rowdata), NULL); if (!SQL_SUCCEEDED(res)) { - ast_log(LOG_WARNING, "SQL Get Data error!\n[%s]\n\n", sql); SQLFreeHandle(SQL_HANDLE_STMT, stmt); - return 1; + SCOPE_EXIT_LOG_RTN_VALUE(1, LOG_WARNING, "SQL Get Data error!\n[%s]\n\n", sql); } *messages = atoi(rowdata); SQLFreeHandle(SQL_HANDLE_STMT, stmt); - return 0; + SCOPE_EXIT_RTN_VALUE(0, "messages: %d\n", *messages); } +#undef COUNT_MSGS_SQL_FMT static int inboxcount2(const char *mailbox, int *urgentmsgs, int *newmsgs, int *oldmsgs) { char tmp[PATH_MAX] = ""; struct odbc_obj *obj; char *context; + SCOPE_ENTER(3, "mb: %s", mailbox); if (newmsgs) *newmsgs = 0; @@ -5827,8 +6181,9 @@ static int inboxcount2(const char *mailbox, int *urgentmsgs, int *newmsgs, int * *urgentmsgs = 0; /* If no mailbox, return immediately */ - if (ast_strlen_zero(mailbox)) - return 0; + if (ast_strlen_zero(mailbox)) { + SCOPE_EXIT_RTN_VALUE(0, "No mailbox\n"); + } ast_copy_string(tmp, mailbox, sizeof(tmp)); @@ -5837,7 +6192,7 @@ static int inboxcount2(const char *mailbox, int *urgentmsgs, int *newmsgs, int * char *next, *remaining = tmp; while ((next = strsep(&remaining, " ,"))) { if (inboxcount2(next, urgentmsgs ? &u : NULL, &n, &o)) { - return -1; + SCOPE_EXIT_RTN_VALUE(-1, "Failed to obtain message count for mailbox %s\n", next); } if (urgentmsgs) { *urgentmsgs += u; @@ -5849,7 +6204,7 @@ static int inboxcount2(const char *mailbox, int *urgentmsgs, int *newmsgs, int * *oldmsgs += o; } } - return 0; + SCOPE_EXIT_RTN_VALUE(0, "Urgent: %d New: %d Old: %d\n", urgentmsgs ? *urgentmsgs : 0, newmsgs ? *newmsgs : 0, oldmsgs ? *oldmsgs : 0); } context = strchr(tmp, '@'); @@ -5861,8 +6216,7 @@ static int inboxcount2(const char *mailbox, int *urgentmsgs, int *newmsgs, int * obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return -1; + SCOPE_EXIT_LOG_RTN_VALUE(-1, AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } if (count_messages_in_folder(obj, context, tmp, "INBOX", newmsgs) @@ -5873,7 +6227,7 @@ static int inboxcount2(const char *mailbox, int *urgentmsgs, int *newmsgs, int * } ast_odbc_release_obj(obj); - return 0; + SCOPE_EXIT_RTN_VALUE(0, "Urgent: %d New: %d Old: %d\n", urgentmsgs ? *urgentmsgs : 0, newmsgs ? *newmsgs : 0, oldmsgs ? *oldmsgs : 0); } /*! @@ -5884,6 +6238,8 @@ static int inboxcount2(const char *mailbox, int *urgentmsgs, int *newmsgs, int * * This method is used when ODBC backend is used. * \return The number of messages in this mailbox folder (zero or more). */ +#define MSGCOUNT_SQL_FMT_INBOX "SELECT COUNT(*) FROM %s WHERE dir = '%s%s/%s/INBOX' OR dir = '%s%s/%s/Urgent'" +#define MSGCOUNT_SQL_FMT "SELECT COUNT(*) FROM %s WHERE dir = '%s%s/%s/%s'" static int messagecount(const char *mailbox_id, const char *folder) { struct odbc_obj *obj = NULL; @@ -5892,14 +6248,14 @@ static int messagecount(const char *mailbox_id, const char *folder) int nummsgs = 0; int res; SQLHSTMT stmt = NULL; - char sql[PATH_MAX]; char rowdata[20]; - struct generic_prepare_struct gps = { .sql = sql, .argc = 0 }; + struct generic_prepare_struct gps = { .argc = 0 }; + SCOPE_ENTER(3, "mb: %s folder: %s", mailbox_id, folder); /* If no mailbox, return immediately */ if (ast_strlen_zero(mailbox_id) || separate_mailbox(ast_strdupa(mailbox_id), &mailbox, &context)) { - return 0; + SCOPE_EXIT_RTN_VALUE(0, "Couldn't parse mailbox\n"); } if (ast_strlen_zero(folder)) { @@ -5908,29 +6264,30 @@ static int messagecount(const char *mailbox_id, const char *folder) obj = ast_odbc_request_obj(odbc_database, 0); if (!obj) { - ast_log(AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); - return 0; + SCOPE_EXIT_LOG_RTN_VALUE(0, AST_LOG_WARNING, "Failed to obtain database object for '%s'!\n", odbc_database); } if (!strcmp(folder, "INBOX")) { - snprintf(sql, sizeof(sql), "SELECT COUNT(*) FROM %s WHERE dir = '%s%s/%s/INBOX' OR dir = '%s%s/%s/Urgent'", odbc_table, VM_SPOOL_DIR, context, mailbox, VM_SPOOL_DIR, context, mailbox); + gps.sql = ast_alloca(sizeof(MSGCOUNT_SQL_FMT_INBOX) + odbc_table_len + (strlen(VM_SPOOL_DIR) + strlen(context) + strlen(mailbox) * 2)); + sprintf(gps.sql, MSGCOUNT_SQL_FMT_INBOX, odbc_table, VM_SPOOL_DIR, context, mailbox, VM_SPOOL_DIR, context, mailbox); /* Safe */ } else { - snprintf(sql, sizeof(sql), "SELECT COUNT(*) FROM %s WHERE dir = '%s%s/%s/%s'", odbc_table, VM_SPOOL_DIR, context, mailbox, folder); + gps.sql = ast_alloca(sizeof(MSGCOUNT_SQL_FMT) + odbc_table_len + strlen(VM_SPOOL_DIR) + strlen(context) + strlen(mailbox) + strlen(folder)); + sprintf(gps.sql, MSGCOUNT_SQL_FMT, odbc_table, VM_SPOOL_DIR, context, mailbox, folder); /* Safe */ } stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, &gps); if (!stmt) { - ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s]\n\n", sql); + ast_log(AST_LOG_WARNING, "SQL Execute error!\n[%s]\n\n", gps.sql); goto bail; } res = SQLFetch(stmt); if (!SQL_SUCCEEDED(res)) { - ast_log(AST_LOG_WARNING, "SQL Fetch error!\n[%s]\n\n", sql); + ast_log(AST_LOG_WARNING, "SQL Fetch error!\n[%s]\n\n", gps.sql); goto bail_with_handle; } res = SQLGetData(stmt, 1, SQL_CHAR, rowdata, sizeof(rowdata), NULL); if (!SQL_SUCCEEDED(res)) { - ast_log(AST_LOG_WARNING, "SQL Get Data error!\n[%s]\n\n", sql); + ast_log(AST_LOG_WARNING, "SQL Get Data error!\n[%s]\n\n", gps.sql); goto bail_with_handle; } nummsgs = atoi(rowdata); @@ -5940,8 +6297,10 @@ static int messagecount(const char *mailbox_id, const char *folder) bail: ast_odbc_release_obj(obj); - return nummsgs; + SCOPE_EXIT_RTN_VALUE(nummsgs, "Messages: %d\n", nummsgs); } +#undef MSGCOUNT_SQL_FMT +#undef MSGCOUNT_SQL_FMT_INBOX /*! * \brief Determines if the given folder has messages. @@ -5982,13 +6341,17 @@ static int has_voicemail(const char *mailboxes, const char *folder) * * \return zero on success, -1 on error. */ -static int copy_message(struct ast_channel *chan, struct ast_vm_user *vmu, int imbox, int msgnum, long duration, struct ast_vm_user *recip, char *fmt, char *dir, const char *flag, const char *dest_folder) +static int copy_message(struct ast_channel *chan, struct ast_vm_user *vmu, int imbox, int msgnum, + long duration, struct ast_vm_user *recip, char *fmt, char *dir, const char *flag, + const char *dest_folder) { char fromdir[PATH_MAX], todir[PATH_MAX], frompath[PATH_MAX], topath[PATH_MAX]; const char *frombox = mbox(vmu, imbox); const char *userfolder; int recipmsgnum; int res = 0; + SCOPE_ENTER(3, "mb: %s imb: %d msgnum: %d recip: %s dir: %s dest_folder: %s", + vmu->mailbox, imbox, msgnum, recip->mailbox, dir, dest_folder); ast_log(AST_LOG_NOTICE, "Copying message from %s@%s to %s@%s\n", vmu->mailbox, vmu->context, recip->mailbox, recip->context); @@ -6001,35 +6364,43 @@ static int copy_message(struct ast_channel *chan, struct ast_vm_user *vmu, int i } create_dirpath(todir, sizeof(todir), recip->context, recip->mailbox, userfolder); + ast_trace(-1, "todir: %s\n", todir); if (!dir) make_dir(fromdir, sizeof(fromdir), vmu->context, vmu->mailbox, frombox); else ast_copy_string(fromdir, dir, sizeof(fromdir)); + ast_trace(-1, "fromdir: %s\n", fromdir); + make_file(frompath, sizeof(frompath), fromdir, msgnum); + ast_trace(-1, "frompath: %s\n", frompath); + make_dir(todir, sizeof(todir), recip->context, recip->mailbox, userfolder); + ast_trace(-1, "todir: %s\n", todir); - if (vm_lock_path(todir)) - return ERROR_LOCK_PATH; + if (vm_lock_path(todir)) { + SCOPE_EXIT_RTN_VALUE(ERROR_LOCK_PATH); + } + + recipmsgnum = LAST_MSG_INDEX(todir) + 1; + ast_trace(-1, "recip msgnum: %d\n", recipmsgnum); - recipmsgnum = last_message_index(todir) + 1; if (recipmsgnum < recip->maxmsg - (imbox ? 0 : inprocess_count(vmu->mailbox, vmu->context, 0))) { + int exists = 0; + make_file(topath, sizeof(topath), todir, recipmsgnum); -#ifndef ODBC_STORAGE - if (EXISTS(fromdir, msgnum, frompath, chan ? ast_channel_language(chan) : "")) { - COPY(fromdir, msgnum, todir, recipmsgnum, recip->mailbox, recip->context, frompath, topath); + ast_trace(-1, "topath: %s\n", topath); + + exists = SCOPE_CALL_WITH_INT_RESULT(-1, EXISTS, fromdir, msgnum, frompath, chan ? ast_channel_language(chan) : ""); + if (exists) { + SCOPE_CALL(-1, COPY, fromdir, msgnum, todir, recipmsgnum, recip->mailbox, recip->context, frompath, topath); } else { -#endif - /* If we are prepending a message for ODBC, then the message already - * exists in the database, but we want to force copying from the - * filesystem (since only the FS contains the prepend). */ - copy_plain_file(frompath, topath); - STORE(todir, recip->mailbox, recip->context, recipmsgnum, chan, recip, fmt, duration, NULL, NULL, NULL); - vm_delete(topath); -#ifndef ODBC_STORAGE + SCOPE_CALL(-1, copy_plain_file,frompath, topath); + SCOPE_CALL(-1, STORE, todir, recip->mailbox, recip->context, recipmsgnum, chan, recip, fmt, duration, NULL, NULL, NULL); + SCOPE_CALL(-1, vm_delete, topath); + } -#endif } else { ast_log(AST_LOG_ERROR, "Recipient mailbox %s@%s is full\n", recip->mailbox, recip->context); res = -1; @@ -6043,7 +6414,7 @@ static int copy_message(struct ast_channel *chan, struct ast_vm_user *vmu, int i flag); } - return res; + SCOPE_EXIT_RTN_VALUE(res, "Done. RC: %d\n", res); } #endif #if !(defined(IMAP_STORAGE) || defined(ODBC_STORAGE)) @@ -6500,9 +6871,9 @@ static int msg_create_from_file(struct ast_vm_recording_data *recdata) #else /* Check to see if the mailbox is full for ODBC/File storage */ - ast_debug(3, "mailbox = %d : inprocess = %d\n", count_messages(recipient, dir), + ast_debug(3, "mailbox = %d : inprocess = %d\n", COUNT(recipient, dir), inprocess_count(recipient->mailbox, recipient->context, 0)); - if (count_messages(recipient, dir) > recipient->maxmsg - inprocess_count(recipient->mailbox, recipient->context, +1)) { + if (COUNT(recipient, dir) > recipient->maxmsg - inprocess_count(recipient->mailbox, recipient->context, +1)) { ast_log(AST_LOG_WARNING, "Didn't copy to voicemail. Mailbox for %s@%s is full.\n", recipient->mailbox, recipient->context); inprocess_count(recipient->mailbox, recipient->context, -1); free_user(recipient); @@ -6510,7 +6881,7 @@ static int msg_create_from_file(struct ast_vm_recording_data *recdata) return -1; } - msgnum = last_message_index(dir) + 1; + msgnum = LAST_MSG_INDEX(dir) + 1; #endif /* Lock the directory receiving the voicemail since we want it to still exist when we attempt to copy the voicemail. @@ -6666,9 +7037,10 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ const char *code; const char *alldtmf = "0123456789ABCD*#"; char flag[80]; + SCOPE_ENTER(3, "%s: %s\n", ast_channel_name(chan), ext); if (!tmp) { - return -1; + SCOPE_EXIT_RTN_VALUE(-1, "Failed to allocate memory for tmp\n"); } ast_str_set(&tmp, 0, "%s", ext); @@ -6700,10 +7072,10 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ ast_debug(3, "Before find_user\n"); memset(&svm, 0, sizeof(svm)); if (!(vmu = find_user(&svm, context, ext))) { - ast_log(AST_LOG_WARNING, "No entry in voicemail config file for '%s'\n", ext); pbx_builtin_setvar_helper(chan, "VMSTATUS", "FAILED"); ast_free(tmp); - return res; + SCOPE_EXIT_LOG_RTN_VALUE(res, LOG_WARNING, + "%s: Exten: %s: No entry in voicemail config file for '%s'\n", ast_channel_name(chan), ext, ext); } /* If maxmsg is zero, act as a "greetings only" voicemail: Exit successfully without recording */ @@ -6728,22 +7100,27 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ } else if (ast_test_flag(options, OPT_UNAVAIL_GREETING)) { snprintf(prefile, sizeof(prefile), "%s%s/%s/unavail", VM_SPOOL_DIR, vmu->context, ext); } + ast_trace(-1, "prefile: %s\n", prefile); /* Set the path to the tmpfile as VM_SPOOL_DIR/context/ext/temp and attempt to create the folder structure. */ snprintf(tempfile, sizeof(tempfile), "%s%s/%s/temp", VM_SPOOL_DIR, vmu->context, ext); + ast_trace(-1, "tempfile: %s\n", tempfile); if ((res = create_dirpath(tmpdir, sizeof(tmpdir), vmu->context, ext, "tmp"))) { - ast_log(AST_LOG_WARNING, "Failed to make directory (%s)\n", tempfile); free_user(vmu); ast_free(tmp); - return -1; + SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_WARNING, + "%s: Exten: %s: Failed to make directory (%s)\n", ast_channel_name(chan), ext, tempfile); } - RETRIEVE(tempfile, -1, vmu->mailbox, vmu->context); - if (ast_fileexists(tempfile, NULL, NULL) > 0) + SCOPE_CALL(-1, RETRIEVE, tempfile, -1, vmu->mailbox, vmu->context); + if (ast_fileexists(tempfile, NULL, NULL) > 0) { ast_copy_string(prefile, tempfile, sizeof(prefile)); + ast_trace(-1, "new prefile: %s\n", prefile); + } + + SCOPE_CALL(-1, DISPOSE, tempfile, -1); - DISPOSE(tempfile, -1); /* It's easier just to try to make it than to check for its existence */ #ifndef IMAP_STORAGE create_dirpath(dir, sizeof(dir), vmu->context, ext, "INBOX"); @@ -6804,10 +7181,12 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ /* Play the beginning intro if desired */ if (!ast_strlen_zero(prefile)) { -#ifdef ODBC_STORAGE - int success = +#if defined(ODBC_STORAGE) + int success = SCOPE_CALL_WITH_INT_RESULT(-1, RETRIEVE, prefile, -1, ext, context); +#elif defined(IMAP_STORAGE) + SCOPE_CALL(-1, RETRIEVE, prefile, -1, ext, context); #endif - RETRIEVE(prefile, -1, ext, context); + if (ast_fileexists(prefile, NULL, NULL) > 0) { if (ast_streamfile(chan, prefile, ast_channel_language(chan)) > -1) { /* We know we have a greeting at this point, so squelch the instructions @@ -6820,21 +7199,20 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ #ifdef ODBC_STORAGE if (success == -1) { /* We couldn't retrieve the file from the database, but we found it on the file system. Let's put it in the database. */ - ast_debug(1, "Greeting not retrieved from database, but found in file storage. Inserting into database\n"); - store_file(prefile, vmu->mailbox, vmu->context, -1); + ast_trace(-1, "Greeting '%s' not retrieved from database, but found in file storage. Inserting into database\n", prefile); + SCOPE_CALL(-1, odbc_store_message, prefile, vmu->mailbox, vmu->context, -1); } #endif } else { - ast_debug(1, "%s doesn't exist, doing what we can\n", prefile); + ast_trace(-1, "%s doesn't exist, doing what we can\n", prefile); res = invent_message(chan, vmu->context, ext, ast_test_flag(options, OPT_BUSY_GREETING), ecodes); } - DISPOSE(prefile, -1); + SCOPE_CALL(-1, DISPOSE, prefile, -1); if (res < 0) { - ast_debug(1, "Hang up during prefile playback\n"); free_user(vmu); pbx_builtin_setvar_helper(chan, "VMSTATUS", "FAILED"); ast_free(tmp); - return -1; + SCOPE_EXIT_RTN_VALUE(-1, "Hang up during prefile playback\n"); } } if (res == '#') { @@ -6864,7 +7242,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ free_user(vmu); pbx_builtin_setvar_helper(chan, "VMSTATUS", "USEREXIT"); ast_free(tmp); - return 0; + SCOPE_EXIT_RTN_VALUE(0, "User escaped with '*'\n"); } /* Check for a '0' here */ @@ -6883,7 +7261,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ } free_user(vmu); ast_free(tmp); - return OPERATOR_EXIT; + SCOPE_EXIT_RTN_VALUE(OPERATOR_EXIT, "User escaped with '0'\n"); } /* Allow all other digits to exit Voicemail and return to the dialplan */ @@ -6894,7 +7272,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ free_user(vmu); ast_free(tmp); pbx_builtin_setvar_helper(chan, "VMSTATUS", "USEREXIT"); - return res; + SCOPE_EXIT_RTN_VALUE(res, "User escaped back to dialplan '%c'\n", res); } if (greeting_only) { @@ -6908,7 +7286,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ free_user(vmu); pbx_builtin_setvar_helper(chan, "VMSTATUS", "FAILED"); ast_free(tmp); - return -1; + SCOPE_EXIT_RTN_VALUE(-1, "Other error '%d'\n", res); } /* The meat of recording the message... All the announcements and beeps have been played*/ if (ast_channel_state(chan) != AST_STATE_UP) { @@ -6954,7 +7332,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ goto leave_vm_out; } #else - if (count_messages(vmu, dir) >= vmu->maxmsg - inprocess_count(vmu->mailbox, vmu->context, +1)) { + if (COUNT(vmu, dir) >= vmu->maxmsg - inprocess_count(vmu->mailbox, vmu->context, +1)) { res = ast_streamfile(chan, "vm-mailboxfull", ast_channel_language(chan)); if (!res) res = ast_waitstream(chan, ""); @@ -6966,6 +7344,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ #endif snprintf(tmptxtfile, sizeof(tmptxtfile), "%s/XXXXXX", tmpdir); + ast_trace(-1, "Tempfile: %s\n", tmptxtfile); txtdes = mkstemp(tmptxtfile); chmod(tmptxtfile, VOICEMAIL_FILE_MODE & ~my_umask); if (txtdes < 0) { @@ -7049,6 +7428,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ date, (long) time(NULL), category ? category : "", msg_id); + ast_trace(-1, "Saving txt file mbox: %s msg_id: %s\n", ext, msg_id); } else { ast_log(AST_LOG_WARNING, "Error opening text file for output\n"); inprocess_count(vmu->mailbox, vmu->context, -1); @@ -7058,7 +7438,8 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ res = ast_streamfile(chan, "vm-mailboxfull", ast_channel_language(chan)); goto leave_vm_out; } - res = play_record_review(chan, NULL, tmptxtfile, vmu->maxsecs, fmt, 1, vmu, &duration, &sound_duration, NULL, options->record_gain, vms, flag, msg_id, 0); + + res = SCOPE_CALL_WITH_INT_RESULT(-1, play_record_review, chan, NULL, tmptxtfile, vmu->maxsecs, fmt, 1, vmu, &duration, &sound_duration, NULL, options->record_gain, vms, flag, msg_id, 0); /* At this point, either we were instructed to make the message Urgent by arguments to VoiceMail or during the review process by the person @@ -7098,7 +7479,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ } } else { #ifndef IMAP_STORAGE - msgnum = last_message_index(dir) + 1; + msgnum = LAST_MSG_INDEX(dir) + 1; #endif make_file(fn, sizeof(fn), dir, msgnum); @@ -7110,7 +7491,12 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ #endif snprintf(txtfile, sizeof(txtfile), "%s.txt", fn); + + ast_trace(-1, "Renaming recordings '%s' -> fn '%s'\n", tmptxtfile, fn); + /* ast_filerename renames the recordings but not the txt file */ ast_filerename(tmptxtfile, fn, NULL); + + ast_trace(-1, "Renaming txt file '%s' -> fn '%s'\n", tmptxtfile, txtfile); rename(tmptxtfile, txtfile); inprocess_count(vmu->mailbox, vmu->context, -1); @@ -7128,7 +7514,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ * ODBC storage does the entire copy with SQL. */ if (ast_fileexists(fn, NULL, NULL) > 0) { - STORE(dir, vmu->mailbox, vmu->context, msgnum, chan, vmu, fmt, duration, vms, flag, msg_id); + SCOPE_CALL(-1, STORE, dir, vmu->mailbox, vmu->context, msgnum, chan, vmu, fmt, duration, vms, flag, msg_id); } /* Are there to be more recipients of this message? */ @@ -7166,7 +7552,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ /* Disposal needs to happen after the optional move and copy */ if (ast_fileexists(fn, NULL, NULL)) { - DISPOSE(dir, msgnum); + SCOPE_CALL(-1, DISPOSE, dir, msgnum); } } } @@ -7204,7 +7590,7 @@ static int leave_voicemail(struct ast_channel *chan, char *ext, struct leave_vm_ #endif ast_free(tmp); - return res; + SCOPE_EXIT_RTN_VALUE(res, "Done: '%d'\n", res); } #if !defined(IMAP_STORAGE) @@ -7304,41 +7690,47 @@ static int save_to_folder(struct ast_vm_user *vmu, struct vm_state *vms, int msg char ddir[PATH_MAX]; const char *dbox = mbox(vmu, box); int x, i; + SCOPE_ENTER(3, "dir: %s msg: %d box: %d dbox: %s move? %d \n", dir, msg, box, dbox, move); + create_dirpath(ddir, sizeof(ddir), context, username, dbox); + ast_trace(-1, "ddir: %s\n", ddir); - if (vm_lock_path(ddir)) - return ERROR_LOCK_PATH; + if (vm_lock_path(ddir)) { + SCOPE_EXIT_RTN_VALUE(ERROR_LOCK_PATH, "Failed to lock path %s\n", ddir); + } - x = last_message_index(ddir) + 1; + x = LAST_MSG_INDEX(ddir) + 1; if (box == 10 && x >= vmu->maxdeletedmsg) { /* "Deleted" folder*/ + ast_trace(-1, "Deleting message %d\n", msg); x--; for (i = 1; i <= x; i++) { /* Push files down a "slot". The oldest file (msg0000) will be deleted. */ make_file(sfn, sizeof(sfn), ddir, i); make_file(dfn, sizeof(dfn), ddir, i - 1); if (EXISTS(ddir, i, sfn, NULL)) { - RENAME(ddir, i, vmu->mailbox, vmu->context, ddir, i - 1, sfn, dfn); + SCOPE_CALL(-1, RENAME, ddir, i, vmu->mailbox, vmu->context, ddir, i - 1, sfn, dfn); } else break; } } else { if (x >= vmu->maxmsg) { ast_unlock_path(ddir); - return ERROR_MAX_MSGS; + SCOPE_EXIT_RTN_VALUE(ERROR_MAX_MSGS, "Max messages reached\n"); } } make_file(sfn, sizeof(sfn), dir, msg); make_file(dfn, sizeof(dfn), ddir, x); if (strcmp(sfn, dfn)) { - COPY(dir, msg, ddir, x, username, context, sfn, dfn); + ast_trace(-1, "Copying message '%s' to '%s'\n", sfn, dfn); + SCOPE_CALL(-1, COPY, dir, msg, ddir, x, username, context, sfn, dfn); } ast_unlock_path(ddir); if (newmsg) { *newmsg = x; } - return 0; + SCOPE_EXIT_RTN_VALUE(0, "Done\n"); #endif } @@ -7982,8 +8374,9 @@ static int get_folder2(struct ast_channel *chan, char *fn, int start) * This is invoked from forward_message() when performing a forward operation (option 8 from main menu). * \return zero on success, -1 on error. */ -static int vm_forwardoptions(struct ast_channel *chan, struct ast_vm_user *vmu, char *curdir, int curmsg, char *vm_fmts, - char *context, signed char record_gain, long *duration, struct vm_state *vms, char *flag) +static int vm_forwardoptions(struct ast_channel *chan, struct ast_vm_user *vmu, char *curdir, + int curmsg, char *vm_fmts, char *context, signed char record_gain, long *duration, + struct vm_state *vms, char *flag) { int cmd = 0; int retries = 0, prepend_duration = 0, already_recorded = 0; @@ -7997,9 +8390,11 @@ static int vm_forwardoptions(struct ast_channel *chan, struct ast_vm_user *vmu, const char *msg_id = NULL; #endif const char *duration_str; + SCOPE_ENTER(3, "mbox: %s msgnum: %d curdir: %s", vmu->mailbox, curmsg, curdir); /* Must always populate duration correctly */ make_file(msgfile, sizeof(msgfile), curdir, curmsg); + ast_trace(-1, "msgfile: %s\n", msgfile); strcpy(textfile, msgfile); strcpy(backup, msgfile); strcpy(backup_textfile, msgfile); @@ -8036,8 +8431,11 @@ static int vm_forwardoptions(struct ast_channel *chan, struct ast_vm_user *vmu, #else /* prepend a message to the current message, update the metadata and return */ + ast_trace(-1, "Prepending to message %d\n", curmsg); make_file(msgfile, sizeof(msgfile), curdir, curmsg); + ast_trace(-1, "msgfile: %s\n", msgfile); + strcpy(textfile, msgfile); strncat(textfile, ".txt", sizeof(textfile) - 1); *duration = 0; @@ -8051,10 +8449,12 @@ static int vm_forwardoptions(struct ast_channel *chan, struct ast_vm_user *vmu, /* Back up the original file, so we can retry the prepend and restore it after forward. */ #ifndef IMAP_STORAGE if (already_recorded) { + ast_trace(-1, "Restoring '%s' to '%s'\n", backup, msgfile); ast_filecopy(backup, msgfile, NULL); copy(backup_textfile, textfile); } else { + ast_trace(-1, "Backing up '%s' to '%s'\n", backup, msgfile); ast_filecopy(msgfile, backup, NULL); copy(textfile, backup_textfile); } @@ -8064,7 +8464,7 @@ static int vm_forwardoptions(struct ast_channel *chan, struct ast_vm_user *vmu, if (record_gain) ast_channel_setoption(chan, AST_OPTION_RXGAIN, &record_gain, sizeof(record_gain), 0); - cmd = ast_play_and_prepend(chan, NULL, msgfile, 0, vm_fmts, &prepend_duration, NULL, 1, silencethreshold, maxsilence); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, ast_play_and_prepend, chan, NULL, msgfile, 0, vm_fmts, &prepend_duration, NULL, 1, silencethreshold, maxsilence); if (cmd == 'S') { /* If we timed out, tell the user it didn't work properly and clean up the files */ ast_stream_and_wait(chan, vm_pls_try_again, ""); /* this might be removed if a proper vm_prepend_timeout is ever recorded */ @@ -8085,6 +8485,7 @@ static int vm_forwardoptions(struct ast_channel *chan, struct ast_vm_user *vmu, char duration_buf[12]; *duration += prepend_duration; + ast_trace(-1, "Prepending duration: %d total duration: %ld\n", prepend_duration, *duration); msg_cat = ast_category_get(msg_cfg, "message", NULL); snprintf(duration_buf, sizeof(duration_buf), "%ld", *duration); if (!ast_variable_update(msg_cat, "duration", duration_buf, NULL, 0)) { @@ -8135,13 +8536,15 @@ static int vm_forwardoptions(struct ast_channel *chan, struct ast_vm_user *vmu, if (already_recorded && cmd == -1) { /* restore original message if prepention cancelled */ + ast_trace(-1, "Restoring '%s' to '%s'\n", backup, msgfile); ast_filerename(backup, msgfile, NULL); rename(backup_textfile, textfile); } - if (cmd == 't' || cmd == 'S') /* XXX entering this block with a value of 'S' is probably no longer possible. */ + if (cmd == 't' || cmd == 'S') { /* XXX entering this block with a value of 'S' is probably no longer possible. */ cmd = 0; - return cmd; + } + SCOPE_EXIT_RTN_VALUE(cmd, "Done. CMD: %d %c\n", cmd, cmd >= 32 && cmd < 127 ? cmd : '?'); } static void queue_mwi_event(const char *channel_id, const char *box, int urgent, int new, int old) @@ -8327,11 +8730,16 @@ static int forward_message(struct ast_channel *chan, char *context, struct vm_st #ifndef IMAP_STORAGE char msgfile[PATH_MAX], textfile[PATH_MAX], backup[PATH_MAX], backup_textfile[PATH_MAX]; #endif + SCOPE_ENTER(3, "%s: user: %s dir: %s msg: %d\n", ast_channel_name(chan), + vms->username, vms->curdir, vms->curmsg); + if (ast_test_flag((&globalflags), VM_FWDURGAUTO)) { ast_copy_string(urgent_str, urgent ? "Urgent" : "", sizeof(urgent_str)); } - if (vms == NULL) return -1; + if (vms == NULL) { + SCOPE_EXIT_RTN_VALUE(-1, "vms is NULL\n"); + } dir = vms->curdir; curmsg = vms->curmsg; @@ -8493,17 +8901,17 @@ static int forward_message(struct ast_channel *chan, char *context, struct vm_st /* play name if available, else play extension number */ snprintf(fn, sizeof(fn), "%s%s/%s/greet", VM_SPOOL_DIR, receiver->context, s); - RETRIEVE(fn, -1, s, receiver->context); + SCOPE_CALL(-1, RETRIEVE, fn, -1, s, receiver->context); if (ast_fileexists(fn, NULL, NULL) > 0) { res = ast_stream_and_wait(chan, fn, ecodes); if (res) { - DISPOSE(fn, -1); + SCOPE_CALL(-1, DISPOSE, fn, -1); return res; } } else { res = ast_say_digit_str(chan, s, ecodes, ast_channel_language(chan)); } - DISPOSE(fn, -1); + SCOPE_CALL(-1, DISPOSE, fn, -1); s = strsep(&stringp, "*"); } @@ -8523,7 +8931,7 @@ static int forward_message(struct ast_channel *chan, char *context, struct vm_st memset(&leave_options, 0, sizeof(leave_options)); leave_options.record_gain = record_gain; leave_options.beeptone = "beep"; - cmd = leave_voicemail(chan, mailbox, &leave_options); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, leave_voicemail, chan, mailbox, &leave_options); } else { /* Forward VoiceMail */ long duration = 0; @@ -8537,7 +8945,7 @@ static int forward_message(struct ast_channel *chan, char *context, struct vm_st #endif memcpy(&vmstmp, vms, sizeof(vmstmp)); - RETRIEVE(dir, curmsg, sender->mailbox, sender->context); + SCOPE_CALL(-1, RETRIEVE, dir, curmsg, sender->mailbox, sender->context); #ifdef IMAP_STORAGE make_file(filename, sizeof(filename), dir, curmsg); strncat(filename, ".txt", sizeof(filename) - strlen(filename) - 1); @@ -8548,7 +8956,7 @@ static int forward_message(struct ast_channel *chan, char *context, struct vm_st } #endif - cmd = vm_forwardoptions(chan, sender, vmstmp.curdir, curmsg, vmfmts, S_OR(context, "default"), record_gain, &duration, &vmstmp, urgent_str); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, vm_forwardoptions, chan, sender, vmstmp.curdir, curmsg, vmfmts, S_OR(context, "default"), record_gain, &duration, &vmstmp, urgent_str); if (!cmd) { AST_LIST_TRAVERSE_SAFE_BEGIN(&extensions, vmtmp, list) { #ifdef IMAP_STORAGE @@ -8582,7 +8990,7 @@ static int forward_message(struct ast_channel *chan, char *context, struct vm_st vmstmp.fn, vmstmp.introfn, fmt, duration, attach_user_voicemail, chan, NULL, urgent_str, msg_id); #else - copy_msg_result = copy_message(chan, sender, 0, curmsg, duration, vmtmp, fmt, dir, urgent_str, NULL); + copy_msg_result = SCOPE_CALL_WITH_INT_RESULT(-1, copy_message, chan, sender, 0, curmsg, duration, vmtmp, fmt, dir, urgent_str, NULL); #endif saved_messages++; AST_LIST_REMOVE_CURRENT(list); @@ -8622,7 +9030,7 @@ static int forward_message(struct ast_channel *chan, char *context, struct vm_st } #endif } - DISPOSE(dir, curmsg); + SCOPE_CALL(-1, DISPOSE, dir, curmsg); #ifndef IMAP_STORAGE if (cmd) { /* assuming hangup, cleanup backup file */ make_file(msgfile, sizeof(msgfile), dir, curmsg); @@ -8640,7 +9048,7 @@ static int forward_message(struct ast_channel *chan, char *context, struct vm_st inprocess_count(vmtmp->mailbox, vmtmp->context, -1); free_user(vmtmp); } - return res ? res : cmd; + SCOPE_EXIT_RTN_VALUE(res ? res : cmd, "Done. res: %d cmd: %d\n", res, cmd); } static int wait_file2(struct ast_channel *chan, struct vm_state *vms, char *file) @@ -8884,6 +9292,8 @@ static int play_message(struct ast_channel *chan, struct ast_vm_user *vmu, struc const char *origtime, *context, *category, *duration, *flag; struct ast_config *msg_cfg; struct ast_flags config_flags = { CONFIG_FLAG_NOCACHE }; + SCOPE_ENTER(3, "%s: user: %s dir: %s msg: %d\n", ast_channel_name(chan), + vms->username, vms->curdir, vms->curmsg); vms->starting = 0; make_file(vms->fn, sizeof(vms->fn), vms->curdir, vms->curmsg); @@ -8895,7 +9305,7 @@ static int play_message(struct ast_channel *chan, struct ast_vm_user *vmu, struc } snprintf(filename, sizeof(filename), "%s.txt", vms->fn); - RETRIEVE(vms->curdir, vms->curmsg, vmu->mailbox, vmu->context); + SCOPE_CALL(-1, RETRIEVE, vms->curdir, vms->curmsg, vmu->mailbox, vmu->context); msg_cfg = ast_config_load(filename, config_flags); if (!valid_config(msg_cfg)) { ast_log(LOG_WARNING, "No message attribute file?!! (%s)\n", filename); @@ -8982,15 +9392,13 @@ static int play_message(struct ast_channel *chan, struct ast_vm_user *vmu, struc } if (!valid_config(msg_cfg)) { - ast_log(AST_LOG_WARNING, "No message attribute file?!! (%s)\n", filename); - return 0; + SCOPE_EXIT_LOG_RTN_VALUE(0, AST_LOG_WARNING, "No message attribute file?!! (%s)\n", filename); } if (!(origtime = ast_variable_retrieve(msg_cfg, "message", "origtime"))) { - ast_log(AST_LOG_WARNING, "No origtime?!\n"); - DISPOSE(vms->curdir, vms->curmsg); + SCOPE_CALL(-1, DISPOSE, vms->curdir, vms->curmsg); ast_config_destroy(msg_cfg); - return 0; + SCOPE_EXIT_LOG_RTN_VALUE(0, AST_LOG_WARNING, "No origtime?!\n"); } cid = ast_strdupa(ast_variable_retrieve(msg_cfg, "message", "callerid")); @@ -9041,8 +9449,8 @@ static int play_message(struct ast_channel *chan, struct ast_vm_user *vmu, struc ast_test_suite_event_notify("USERPRESS", "Message: User pressed %c\r\nDTMF: %c", isprint(res) ? res : '?', isprint(res) ? res : '?'); } - DISPOSE(vms->curdir, vms->curmsg); - return res; + SCOPE_CALL(-1, DISPOSE, vms->curdir, vms->curmsg); + SCOPE_EXIT_RTN_VALUE(res, "Done: RC: %d\n", res); } #ifdef IMAP_STORAGE @@ -9136,6 +9544,8 @@ static int imap_delete_old_greeting (char *dir, struct vm_state *vms) static int open_mailbox(struct vm_state *vms, struct ast_vm_user *vmu, int box) { int count_msg, last_msg; + SCOPE_ENTER(3, "user: %s dir: %s msg: %d box %d\n", + vms->username, vms->curdir, vms->curmsg, box); ast_copy_string(vms->curbox, mbox(vmu, box), sizeof(vms->curbox)); @@ -9148,15 +9558,15 @@ static int open_mailbox(struct vm_state *vms, struct ast_vm_user *vmu, int box) create_dirpath(vms->curdir, sizeof(vms->curdir), vmu->context, vms->username, vms->curbox); /* traverses directory using readdir (or select query for ODBC) */ - count_msg = count_messages(vmu, vms->curdir); + count_msg = COUNT(vmu, vms->curdir); if (count_msg < 0) { - return count_msg; + SCOPE_EXIT_RTN_VALUE(count_msg, "msgs: %d\n", count_msg); } else { vms->lastmsg = count_msg - 1; } if (vm_allocate_dh(vms, vmu, count_msg)) { - return -1; + SCOPE_EXIT_RTN_VALUE(-1, "failed to allocate dh\n"); } /* @@ -9167,22 +9577,21 @@ static int open_mailbox(struct vm_state *vms, struct ast_vm_user *vmu, int box) */ if (vm_lock_path(vms->curdir)) { - ast_log(AST_LOG_ERROR, "Could not open mailbox %s: mailbox is locked\n", vms->curdir); - return ERROR_LOCK_PATH; + SCOPE_EXIT_LOG_RTN_VALUE(ERROR_LOCK_PATH, AST_LOG_ERROR, "Could not open mailbox %s: mailbox is locked\n", vms->curdir); } /* for local storage, checks directory for messages up to MAXMSGLIMIT */ - last_msg = last_message_index(vms->curdir); + last_msg = LAST_MSG_INDEX(vms->curdir); ast_unlock_path(vms->curdir); if (last_msg < -1) { - return last_msg; + SCOPE_EXIT_RTN_VALUE(last_msg, "last msg: %d\n", last_msg); } else if (vms->lastmsg != last_msg) { ast_log(LOG_NOTICE, "Resequencing Mailbox: %s, expected %d but found %d message(s) in box with max threshold of %d.\n", vms->curdir, last_msg + 1, vms->lastmsg + 1, vmu->maxmsg); resequence_mailbox(vmu, vms->curdir, count_msg); } - return 0; + SCOPE_EXIT_RTN_VALUE(0, "Done\n"); } #endif @@ -9195,8 +9604,11 @@ static int close_mailbox(struct vm_state *vms, struct ast_vm_user *vmu) int res = 0, nummsg; char fn2[PATH_MAX]; #endif + SCOPE_ENTER(3, "user: %s dir: %s msg: %d\n", + vms->username, vms->curdir, vms->curmsg); if (vms->lastmsg <= -1) { + ast_trace(-1, "No messages in mailbox\n"); goto done; } @@ -9204,11 +9616,11 @@ static int close_mailbox(struct vm_state *vms, struct ast_vm_user *vmu) #ifndef IMAP_STORAGE /* Get the deleted messages fixed */ if (vm_lock_path(vms->curdir)) { - return ERROR_LOCK_PATH; + SCOPE_EXIT_RTN_VALUE(ERROR_LOCK_PATH, "Could not open mailbox %s: mailbox is locked\n", vms->curdir); } /* update count as message may have arrived while we've got mailbox open */ - last_msg_idx = last_message_index(vms->curdir); + last_msg_idx = LAST_MSG_INDEX(vms->curdir); if (last_msg_idx != vms->lastmsg) { ast_log(AST_LOG_NOTICE, "%d messages received after mailbox opened.\n", last_msg_idx - vms->lastmsg); } @@ -9224,11 +9636,11 @@ static int close_mailbox(struct vm_state *vms, struct ast_vm_user *vmu) vms->curmsg++; make_file(fn2, sizeof(fn2), vms->curdir, vms->curmsg); if (strcmp(vms->fn, fn2)) { - RENAME(vms->curdir, x, vmu->mailbox, vmu->context, vms->curdir, vms->curmsg, vms->fn, fn2); + SCOPE_CALL(-1, RENAME, vms->curdir, x, vmu->mailbox, vmu->context, vms->curdir, vms->curmsg, vms->fn, fn2); } } else if ((!strcasecmp(vms->curbox, "INBOX") || !strcasecmp(vms->curbox, "Urgent")) && vms->heard[x] && ast_test_flag(vmu, VM_MOVEHEARD) && !vms->deleted[x]) { /* Move to old folder before deleting */ - res = save_to_folder(vmu, vms, x, 1, NULL, 0); + res = SCOPE_CALL_WITH_INT_RESULT(-1, save_to_folder, vmu, vms, x, 1, NULL, 0); if (res == ERROR_LOCK_PATH || res == ERROR_MAX_MSGS) { /* If save failed do not delete the message */ ast_log(AST_LOG_WARNING, "Save failed. Not moving message: %s.\n", res == ERROR_LOCK_PATH ? "unable to lock path" : "destination folder full"); @@ -9238,8 +9650,9 @@ static int close_mailbox(struct vm_state *vms, struct ast_vm_user *vmu) } } else if (vms->deleted[x] && vmu->maxdeletedmsg) { /* Move to deleted folder */ - res = save_to_folder(vmu, vms, x, 10, NULL, 0); + res = SCOPE_CALL_WITH_INT_RESULT(-1, save_to_folder, vmu, vms, x, 10, NULL, 0); if (res == ERROR_LOCK_PATH) { + ast_trace(-1, "Unable to lock path. Not moving message to deleted folder.\n"); /* If save failed do not delete the message */ vms->deleted[x] = 0; vms->heard[x] = 0; @@ -9249,8 +9662,9 @@ static int close_mailbox(struct vm_state *vms, struct ast_vm_user *vmu) /* If realtime storage enabled - we should explicitly delete this message, cause RENAME() will overwrite files, but will keep duplicate records in RT-storage */ make_file(vms->fn, sizeof(vms->fn), vms->curdir, x); - if (EXISTS(vms->curdir, x, vms->fn, NULL)) { - DELETE(vms->curdir, x, vms->fn, vmu); + res = SCOPE_CALL_WITH_INT_RESULT(-1, EXISTS, vms->curdir, x, vms->fn, NULL); + if (res) { + SCOPE_CALL(-1, DELETE, vms->curdir, x, vms->fn, vmu); } } } @@ -9259,8 +9673,9 @@ static int close_mailbox(struct vm_state *vms, struct ast_vm_user *vmu) nummsg = x - 1; for (x = vms->curmsg + 1; x <= nummsg; x++) { make_file(vms->fn, sizeof(vms->fn), vms->curdir, x); - if (EXISTS(vms->curdir, x, vms->fn, NULL)) { - DELETE(vms->curdir, x, vms->fn, vmu); + res = SCOPE_CALL_WITH_INT_RESULT(-1, EXISTS, vms->curdir, x, vms->fn, NULL); + if (res) { + SCOPE_CALL(-1, DELETE, vms->curdir, x, vms->fn, vmu); } } ast_unlock_path(vms->curdir); @@ -9293,7 +9708,7 @@ static int close_mailbox(struct vm_state *vms, struct ast_vm_user *vmu) ast_mutex_unlock(&vms->lock); #endif - return 0; + SCOPE_EXIT_RTN_VALUE(0, "Done\n"); } /* In Greek even though we CAN use a syntax like "friends messages" @@ -10837,6 +11252,7 @@ static int vm_options(struct ast_channel *chan, struct ast_vm_user *vmu, struct char prefile[PATH_MAX] = ""; unsigned char buf[256]; int bytes = 0; + SCOPE_ENTER(3, "%s: %s entering mailbox options", ast_channel_name(chan), vms->username); ast_test_suite_event_notify("VMOPTIONS", "Message: entering mailbox options"); if (ast_adsi_available(chan)) { @@ -10853,15 +11269,15 @@ static int vm_options(struct ast_channel *chan, struct ast_vm_user *vmu, struct switch (cmd) { case '1': /* Record your unavailable message */ snprintf(prefile, sizeof(prefile), "%s%s/%s/unavail", VM_SPOOL_DIR, vmu->context, vms->username); - cmd = play_record_review(chan, "vm-rec-unv", prefile, maxgreet, fmtc, 0, vmu, &duration, NULL, NULL, record_gain, vms, NULL, NULL, 0); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_record_review, chan, "vm-rec-unv", prefile, maxgreet, fmtc, 0, vmu, &duration, NULL, NULL, record_gain, vms, NULL, NULL, 0); break; case '2': /* Record your busy message */ snprintf(prefile, sizeof(prefile), "%s%s/%s/busy", VM_SPOOL_DIR, vmu->context, vms->username); - cmd = play_record_review(chan, "vm-rec-busy", prefile, maxgreet, fmtc, 0, vmu, &duration, NULL, NULL, record_gain, vms, NULL, NULL, 0); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_record_review, chan, "vm-rec-busy", prefile, maxgreet, fmtc, 0, vmu, &duration, NULL, NULL, record_gain, vms, NULL, NULL, 0); break; case '3': /* Record greeting */ snprintf(prefile, sizeof(prefile), "%s%s/%s/greet", VM_SPOOL_DIR, vmu->context, vms->username); - cmd = play_record_review(chan, "vm-rec-name", prefile, maxgreet, fmtc, 0, vmu, &duration, NULL, NULL, record_gain, vms, NULL, NULL, 0); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_record_review, chan, "vm-rec-name", prefile, maxgreet, fmtc, 0, vmu, &duration, NULL, NULL, record_gain, vms, NULL, NULL, 0); break; case '4': /* manage the temporary greeting */ cmd = vm_tempgreeting(chan, vmu, vms, fmtc, record_gain); @@ -10929,11 +11345,11 @@ static int vm_options(struct ast_channel *chan, struct ast_vm_user *vmu, struct default: cmd = 0; snprintf(prefile, sizeof(prefile), "%s%s/%s/temp", VM_SPOOL_DIR, vmu->context, vms->username); - RETRIEVE(prefile, -1, vmu->mailbox, vmu->context); + SCOPE_CALL(-1, RETRIEVE, prefile, -1, vmu->mailbox, vmu->context); if (ast_fileexists(prefile, NULL, NULL)) { cmd = ast_play_and_wait(chan, "vm-tmpexists"); } - DISPOSE(prefile, -1); + SCOPE_CALL(-1, DISPOSE, prefile, -1); if (!cmd) { cmd = ast_play_and_wait(chan, "vm-options"); } @@ -10952,7 +11368,7 @@ static int vm_options(struct ast_channel *chan, struct ast_vm_user *vmu, struct } if (cmd == 't') cmd = 0; - return cmd; + SCOPE_EXIT_RTN_VALUE(cmd, "Done\n"); } /*! @@ -11993,6 +12409,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) #ifdef IMAP_STORAGE int deleted = 0; #endif + SCOPE_ENTER(3, "%s:\n", ast_channel_name(chan)); /* Add the vm_state to the active list and keep it active */ vms.lastmsg = -1; @@ -12016,14 +12433,14 @@ static int vm_execmain(struct ast_channel *chan, const char *data) AST_STANDARD_APP_ARGS(args, parse); if (args.argc == 2) { - if (ast_app_parse_options(vm_app_options, &flags, opts, args.argv1)) - return -1; + if (ast_app_parse_options(vm_app_options, &flags, opts, args.argv1)) { + SCOPE_EXIT_LOG_RTN_VALUE(-1, AST_LOG_WARNING, "Invalid option string '%s'\n", args.argv1); + } if (ast_test_flag(&flags, OPT_RECORDGAIN)) { int gain; if (!ast_strlen_zero(opts[OPT_ARG_RECORDGAIN])) { if (sscanf(opts[OPT_ARG_RECORDGAIN], "%30d", &gain) != 1) { - ast_log(AST_LOG_WARNING, "Invalid value '%s' provided for record gain option\n", opts[OPT_ARG_RECORDGAIN]); - return -1; + SCOPE_EXIT_LOG_RTN_VALUE(-1, AST_LOG_WARNING, "Invalid value '%s' provided for record gain option\n", opts[OPT_ARG_RECORDGAIN]); } else { record_gain = (signed char) gain; } @@ -12094,10 +12511,10 @@ static int vm_execmain(struct ast_channel *chan, const char *data) if (!valid) res = vm_authenticate(chan, vms.username, sizeof(vms.username), &vmus, context, prefixstr, skipuser, maxlogins, 0); - ast_debug(1, "After vm_authenticate\n"); + ast_trace(-1, "vm_authenticate user: %s\n", vms.username); if (vms.username[0] == '*') { - ast_debug(1, "user pressed * in context '%s'\n", ast_channel_context(chan)); + ast_trace(-1, "user pressed * in context '%s'\n", ast_channel_context(chan)); /* user entered '*' */ if (!ast_goto_if_exists(chan, ast_channel_context(chan), "a", 1)) { @@ -12119,6 +12536,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) adsi_begin(chan, &useadsi); if (!valid) { + ast_trace(-1, "Invalid user\n"); goto out; } ast_test_suite_event_notify("AUTHENTICATED", "Message: vm_user authenticated"); @@ -12143,38 +12561,46 @@ static int vm_execmain(struct ast_channel *chan, const char *data) } /* Retrieve urgent, old and new message counts */ - ast_debug(1, "Before open_mailbox\n"); - res = open_mailbox(&vms, vmu, OLD_FOLDER); /* Count all messages, even Urgent */ - if (res < 0) + ast_trace(-1, "Before open_mailbox\n"); + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, OLD_FOLDER); /* Count all messages, even Urgent */ + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } vms.oldmessages = vms.lastmsg + 1; - ast_debug(1, "Number of old messages: %d\n", vms.oldmessages); + ast_trace(-1, "Number of old messages: %d\n", vms.oldmessages); /* check INBOX */ - res = open_mailbox(&vms, vmu, NEW_FOLDER); - if (res < 0) + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, NEW_FOLDER); + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } vms.newmessages = vms.lastmsg + 1; - ast_debug(1, "Number of new messages: %d\n", vms.newmessages); + ast_trace(-1, "Number of new messages: %d\n", vms.newmessages); /* Start in Urgent */ in_urgent = 1; - res = open_mailbox(&vms, vmu, 11); /*11 is the Urgent folder */ - if (res < 0) + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, 11); /*11 is the Urgent folder */ + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } vms.urgentmessages = vms.lastmsg + 1; - ast_debug(1, "Number of urgent messages: %d\n", vms.urgentmessages); + ast_trace(-1, "Number of urgent messages: %d\n", vms.urgentmessages); /* Select proper mailbox FIRST!! */ if (play_auto) { ast_test_suite_event_notify("AUTOPLAY", "Message: auto-playing messages"); if (vms.urgentmessages) { in_urgent = 1; - res = open_mailbox(&vms, vmu, 11); + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, 11); } else { in_urgent = 0; - res = open_mailbox(&vms, vmu, play_folder); + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, play_folder); } - if (res < 0) + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } /* If there are no new messages, inform the user and hangup */ if (vms.lastmsg == -1) { @@ -12186,7 +12612,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) } else { if (!vms.newmessages && !vms.urgentmessages && vms.oldmessages) { /* If we only have old messages start here */ - res = open_mailbox(&vms, vmu, OLD_FOLDER); /* Count all messages, even Urgent */ + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, OLD_FOLDER); /* Count all messages, even Urgent */ in_urgent = 0; play_folder = 1; if (res < 0) @@ -12194,7 +12620,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) } else if (!vms.urgentmessages && vms.newmessages) { /* If we have new messages but none are urgent */ in_urgent = 0; - res = open_mailbox(&vms, vmu, NEW_FOLDER); + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, NEW_FOLDER); if (res < 0) goto out; } @@ -12214,11 +12640,13 @@ static int vm_execmain(struct ast_channel *chan, const char *data) /* Timeout */ ast_test_suite_event_notify("TIMEOUT", "Message: response from user timed out"); res = 0; + ast_trace(-1, "Timeout\n"); goto out; } else if (cmd < 0) { /* Hangup */ ast_test_suite_event_notify("HANGUP", "Message: hangup detected"); res = -1; + ast_trace(-1, "Hangup\n"); goto out; } } @@ -12248,6 +12676,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) vms.starting = 1; while ((cmd > -1) && (cmd != 't') && (cmd != '#')) { /* Run main menu */ + ast_trace(-1, "Main menu: %d %c\n", cmd, (cmd >= 32 && cmd <= 126 ? cmd : ' ')); switch (cmd) { case '1': /* First message */ vms.curmsg = 0; @@ -12268,14 +12697,18 @@ static int vm_execmain(struct ast_channel *chan, const char *data) cmd = 0; } else if (cmd > 0) { cmd = cmd - '0'; - res = close_mailbox(&vms, vmu); - if (res == ERROR_LOCK_PATH) + res = SCOPE_CALL_WITH_INT_RESULT(-1, close_mailbox, &vms, vmu); + if (res == ERROR_LOCK_PATH) { + ast_trace(-1, "close mailbox: %d\n", res); goto out; + } /* If folder is not urgent, set in_urgent to zero! */ if (cmd != 11) in_urgent = 0; - res = open_mailbox(&vms, vmu, cmd); - if (res < 0) + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, cmd); + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } play_folder = cmd; cmd = 0; } @@ -12300,6 +12733,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) cmd = advanced_options(chan, vmu, &vms, vms.curmsg, 1, record_gain); if (cmd == ERROR_LOCK_PATH || cmd == OPERATOR_EXIT) { res = cmd; + ast_trace(-1, "advanced options: %d\n", cmd); goto out; } } else { @@ -12312,6 +12746,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) ast_verb(3, "Callback Requested\n"); if (!ast_strlen_zero(vmu->callback) && vms.lastmsg > -1 && !vms.starting) { cmd = advanced_options(chan, vmu, &vms, vms.curmsg, 2, record_gain); + ast_trace(-1, "advanced options: %d\n", cmd); if (cmd == 9) { silentexit = 1; goto out; @@ -12329,6 +12764,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) cmd = advanced_options(chan, vmu, &vms, vms.curmsg, 3, record_gain); if (cmd == ERROR_LOCK_PATH) { res = cmd; + ast_trace(-1, "advanced options: %d\n", cmd); goto out; } } else { @@ -12341,6 +12777,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) cmd = dialout(chan, vmu, NULL, vmu->dialout); if (cmd == 9) { silentexit = 1; + ast_trace(-1, "dialout: %d\n", cmd); goto out; } } else { @@ -12351,9 +12788,10 @@ static int vm_execmain(struct ast_channel *chan, const char *data) case '5': /* Leave VoiceMail */ if (ast_test_flag(vmu, VM_SVMAIL)) { - cmd = forward_message(chan, context, &vms, vmu, vmfmts, 1, record_gain, 0); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, forward_message, chan, context, &vms, vmu, vmfmts, 1, record_gain, 0); if (cmd == ERROR_LOCK_PATH || cmd == OPERATOR_EXIT) { res = cmd; + ast_trace(-1, "forward message: %d\n", cmd); goto out; } } else { @@ -12408,7 +12846,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) ast_test_suite_event_notify("PREVMSG", "Message: browsing message %d\r\nVoicemail: %d", vms.curmsg - 1, vms.curmsg - 1); if (vms.curmsg > 0) { vms.curmsg--; - cmd = play_message(chan, vmu, &vms); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_message, chan, vmu, &vms); } else { /* Check if we were listening to new messages. If so, go to Urgent messages @@ -12417,12 +12855,16 @@ static int vm_execmain(struct ast_channel *chan, const char *data) if (in_urgent == 0 && vms.urgentmessages > 0) { /* Check for Urgent messages */ in_urgent = 1; - res = close_mailbox(&vms, vmu); - if (res == ERROR_LOCK_PATH) + res = SCOPE_CALL_WITH_INT_RESULT(-1, close_mailbox, &vms, vmu); + if (res == ERROR_LOCK_PATH) { + ast_trace(-1, "close mailbox: %d\n", res); goto out; - res = open_mailbox(&vms, vmu, 11); /* Open Urgent folder */ - if (res < 0) + } + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, 11); /* Open Urgent folder */ + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } ast_debug(1, "No more new messages, opened INBOX and got %d Urgent messages\n", vms.lastmsg + 1); vms.curmsg = vms.lastmsg; if (vms.lastmsg < 0) { @@ -12430,7 +12872,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) } } else if (ast_test_flag(vmu, VM_MESSAGEWRAP) && vms.lastmsg > 0) { vms.curmsg = vms.lastmsg; - cmd = play_message(chan, vmu, &vms); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_message, chan, vmu, &vms); } else { cmd = ast_play_and_wait(chan, "vm-nomore"); } @@ -12440,7 +12882,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) ast_test_suite_event_notify("PREVMSG", "Message: browsing message %d\r\nVoicemail: %d", vms.curmsg + 1, vms.curmsg + 1); if (vms.curmsg < vms.lastmsg) { vms.curmsg++; - cmd = play_message(chan, vmu, &vms); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_message, chan, vmu, &vms); } else { if (in_urgent && vms.newmessages > 0) { /* Check if we were listening to urgent @@ -12448,12 +12890,16 @@ static int vm_execmain(struct ast_channel *chan, const char *data) * instead of saying "no more messages" */ in_urgent = 0; - res = close_mailbox(&vms, vmu); - if (res == ERROR_LOCK_PATH) + res = SCOPE_CALL_WITH_INT_RESULT(-1, close_mailbox, &vms, vmu); + if (res == ERROR_LOCK_PATH) { + ast_trace(-1, "close mailbox: %d\n", res); goto out; - res = open_mailbox(&vms, vmu, NEW_FOLDER); - if (res < 0) + } + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, NEW_FOLDER); + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } ast_debug(1, "No more urgent messages, opened INBOX and got %d new messages\n", vms.lastmsg + 1); vms.curmsg = -1; if (vms.lastmsg < 0) { @@ -12461,7 +12907,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) } } else if (ast_test_flag(vmu, VM_MESSAGEWRAP) && vms.lastmsg > 0) { vms.curmsg = 0; - cmd = play_message(chan, vmu, &vms); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_message, chan, vmu, &vms); } else { cmd = ast_play_and_wait(chan, "vm-nomore"); } @@ -12498,10 +12944,10 @@ static int vm_execmain(struct ast_channel *chan, const char *data) if (ast_test_flag(vmu, VM_SKIPAFTERCMD)) { if (vms.curmsg < vms.lastmsg) { vms.curmsg++; - cmd = play_message(chan, vmu, &vms); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_message, chan, vmu, &vms); } else if (ast_test_flag(vmu, VM_MESSAGEWRAP) && vms.lastmsg > 0) { vms.curmsg = 0; - cmd = play_message(chan, vmu, &vms); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_message, chan, vmu, &vms); } else { /* Check if we were listening to urgent messages. If so, go to regular new messages @@ -12510,12 +12956,16 @@ static int vm_execmain(struct ast_channel *chan, const char *data) if (in_urgent == 1) { /* Check for new messages */ in_urgent = 0; - res = close_mailbox(&vms, vmu); - if (res == ERROR_LOCK_PATH) + res = SCOPE_CALL_WITH_INT_RESULT(-1, close_mailbox, &vms, vmu); + if (res == ERROR_LOCK_PATH) { + ast_trace(-1, "close mailbox: %d\n", res); goto out; - res = open_mailbox(&vms, vmu, NEW_FOLDER); - if (res < 0) + } + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, NEW_FOLDER); + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } ast_debug(1, "No more urgent messages, opened INBOX and got %d new messages\n", vms.lastmsg + 1); vms.curmsg = -1; if (vms.lastmsg < 0) { @@ -12535,9 +12985,10 @@ static int vm_execmain(struct ast_channel *chan, const char *data) case '8': /* Forward the current message */ if (vms.lastmsg > -1) { - cmd = forward_message(chan, context, &vms, vmu, vmfmts, 0, record_gain, in_urgent); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, forward_message, chan, context, &vms, vmu, vmfmts, 0, record_gain, in_urgent); if (cmd == ERROR_LOCK_PATH) { res = cmd; + ast_trace(-1, "forward message: %d\n", res); goto out; } } else { @@ -12548,12 +12999,16 @@ static int vm_execmain(struct ast_channel *chan, const char *data) if (in_urgent == 1 && vms.newmessages > 0) { /* Check for new messages */ in_urgent = 0; - res = close_mailbox(&vms, vmu); - if (res == ERROR_LOCK_PATH) + res = SCOPE_CALL_WITH_INT_RESULT(-1, close_mailbox, &vms, vmu); + if (res == ERROR_LOCK_PATH) { + ast_trace(-1, "close mailbox: %d\n", res); goto out; - res = open_mailbox(&vms, vmu, NEW_FOLDER); - if (res < 0) + } + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, NEW_FOLDER); + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } ast_debug(1, "No more urgent messages, opened INBOX and got %d new messages\n", vms.lastmsg + 1); vms.curmsg = -1; if (vms.lastmsg < 0) { @@ -12582,9 +13037,10 @@ static int vm_execmain(struct ast_channel *chan, const char *data) break; } else if (cmd > 0) { box = cmd = cmd - '0'; - cmd = save_to_folder(vmu, &vms, vms.curmsg, cmd, NULL, 0); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, save_to_folder, vmu, &vms, vms.curmsg, cmd, NULL, 0); if (cmd == ERROR_LOCK_PATH) { res = cmd; + ast_trace(-1, "save to folder: %d\n", res); goto out; #ifndef IMAP_STORAGE } else if (!cmd) { @@ -12613,10 +13069,10 @@ static int vm_execmain(struct ast_channel *chan, const char *data) if (ast_test_flag((&globalflags), VM_SKIPAFTERCMD)) { if (vms.curmsg < vms.lastmsg) { vms.curmsg++; - cmd = play_message(chan, vmu, &vms); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_message, chan, vmu, &vms); } else if (ast_test_flag(vmu, VM_MESSAGEWRAP) && vms.lastmsg > 0) { vms.curmsg = 0; - cmd = play_message(chan, vmu, &vms); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, play_message, chan, vmu, &vms); } else { /* Check if we were listening to urgent messages. If so, go to regular new messages @@ -12625,12 +13081,16 @@ static int vm_execmain(struct ast_channel *chan, const char *data) if (in_urgent == 1 && vms.newmessages > 0) { /* Check for new messages */ in_urgent = 0; - res = close_mailbox(&vms, vmu); - if (res == ERROR_LOCK_PATH) + res = SCOPE_CALL_WITH_INT_RESULT(-1, close_mailbox, &vms, vmu); + if (res == ERROR_LOCK_PATH) { + ast_trace(-1, "close mailbox: %d\n", res); goto out; - res = open_mailbox(&vms, vmu, NEW_FOLDER); - if (res < 0) + } + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, NEW_FOLDER); + if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; + } ast_debug(1, "No more urgent messages, opened INBOX and got %d new messages\n", vms.lastmsg + 1); vms.curmsg = -1; if (vms.lastmsg < 0) { @@ -12674,12 +13134,13 @@ static int vm_execmain(struct ast_channel *chan, const char *data) cmd = 0; break; case '0': /* Mailbox options */ - cmd = vm_options(chan, vmu, &vms, vmfmts, record_gain); + cmd = SCOPE_CALL_WITH_INT_RESULT(-1, vm_options,chan, vmu, &vms, vmfmts, record_gain); if (useadsi) adsi_status(chan, &vms); /* Reopen play_folder */ - res = open_mailbox(&vms, vmu, play_folder); + res = SCOPE_CALL_WITH_INT_RESULT(-1, open_mailbox, &vms, vmu, play_folder); if (res < 0) { + ast_trace(-1, "open mailbox: %d\n", res); goto out; } vms.starting = 1; @@ -12714,8 +13175,9 @@ static int vm_execmain(struct ast_channel *chan, const char *data) if (useadsi) ast_adsi_unload_session(chan); } - if (vmu) - close_mailbox(&vms, vmu); + if (vmu) { + SCOPE_CALL(-1, close_mailbox, &vms, vmu); + } if (valid) { int new = 0, old = 0, urgent = 0; snprintf(ext_context, sizeof(ext_context), "%s@%s", vms.username, vmu->context); @@ -12749,7 +13211,7 @@ static int vm_execmain(struct ast_channel *chan, const char *data) #ifdef IMAP_STORAGE pthread_setspecific(ts_vmstate.key, NULL); #endif - return res; + SCOPE_EXIT_RTN_VALUE(res, "Done. RC: %d\n", res); } static int vm_exec(struct ast_channel *chan, const char *data) @@ -12763,6 +13225,7 @@ static int vm_exec(struct ast_channel *chan, const char *data) AST_APP_ARG(argv0); AST_APP_ARG(argv1); ); + SCOPE_ENTER(3, "%s\n", ast_channel_name(chan)); memset(&leave_options, 0, sizeof(leave_options)); @@ -12770,15 +13233,15 @@ static int vm_exec(struct ast_channel *chan, const char *data) tmp = ast_strdupa(data); AST_STANDARD_APP_ARGS(args, tmp); if (args.argc == 2) { - if (ast_app_parse_options(vm_app_options, &flags, opts, args.argv1)) - return -1; + if (ast_app_parse_options(vm_app_options, &flags, opts, args.argv1)) { + SCOPE_EXIT_RTN_VALUE(-1, "parse options failed for '%s'\n", args.argv1); + } ast_copy_flags(&leave_options, &flags, OPT_SILENT | OPT_SILENT_IF_GREET | OPT_BUSY_GREETING | OPT_UNAVAIL_GREETING | OPT_MESSAGE_Urgent | OPT_MESSAGE_PRIORITY | OPT_DTMFEXIT); if (ast_test_flag(&flags, OPT_RECORDGAIN)) { int gain; if (sscanf(opts[OPT_ARG_RECORDGAIN], "%30d", &gain) != 1) { - ast_log(AST_LOG_WARNING, "Invalid value '%s' provided for record gain option\n", opts[OPT_ARG_RECORDGAIN]); - return -1; + SCOPE_EXIT_LOG_RTN_VALUE(-1, AST_LOG_WARNING, "Invalid value '%s' provided for record gain option\n", opts[OPT_ARG_RECORDGAIN]); } else { leave_options.record_gain = (signed char) gain; } @@ -12796,10 +13259,12 @@ static int vm_exec(struct ast_channel *chan, const char *data) } else { char temp[256]; res = ast_app_getdata(chan, "vm-whichbox", temp, sizeof(temp) - 1, 0); - if (res < 0) - return res; - if (ast_strlen_zero(temp)) - return 0; + if (res < 0) { + SCOPE_EXIT_RTN_VALUE(res, "getdata failed. RC: %d", res); + } + if (ast_strlen_zero(temp)) { + SCOPE_EXIT_RTN_VALUE(0); + } args.argv0 = ast_strdupa(temp); } @@ -12811,7 +13276,7 @@ static int vm_exec(struct ast_channel *chan, const char *data) } } - res = leave_voicemail(chan, args.argv0, &leave_options); + res = SCOPE_CALL_WITH_INT_RESULT(-1, leave_voicemail, chan, args.argv0, &leave_options); if (res == 't') { ast_play_and_wait(chan, "vm-goodbye"); res = 0; @@ -12827,7 +13292,7 @@ static int vm_exec(struct ast_channel *chan, const char *data) res = 0; } - return res; + SCOPE_EXIT_RTN_VALUE(res, "Done. RC: %d", res); } static int add_message_id(struct ast_config *msg_cfg, char *dir, int msg, char *filename, char *id, size_t id_size, struct ast_vm_user *vmu, int folder) @@ -14463,10 +14928,18 @@ static int actual_load_config(int reload, struct ast_config *cfg, struct ast_con if ((val = ast_variable_retrieve(cfg, "general", "odbcstorage"))) { ast_copy_string(odbc_database, val, sizeof(odbc_database)); } + strcpy(odbc_table, "voicemessages"); if ((val = ast_variable_retrieve(cfg, "general", "odbctable"))) { ast_copy_string(odbc_table, val, sizeof(odbc_table)); } + odbc_table_len = strlen(odbc_table); + + ast_set2_flag((&globalflags), 0, VM_ODBC_AUDIO_ON_DISK); + if (!(val = ast_variable_retrieve(cfg, "general", "odbc_audio_on_disk"))) + val = "no"; + ast_set2_flag((&globalflags), ast_true(val), VM_ODBC_AUDIO_ON_DISK); + #endif /* Mail command */ strcpy(mailcmd, SENDMAIL); @@ -16256,13 +16729,14 @@ static int play_record_review(struct ast_channel *chan, char *playfile, char *re char *acceptdtmf = "#"; char *canceldtmf = ""; int canceleddtmf = 0; - + SCOPE_ENTER(3, "%s: rf: %s fmt: %s type: %s vmu: %s\n", + ast_channel_name(chan), recordfile, fmt, outsidecaller ? "msg" : "greeting", + vmu->mailbox); /* Note that urgent and private are for flagging messages as such in the future */ /* barf if no pointer passed to store duration in */ if (duration == NULL) { - ast_log(AST_LOG_WARNING, "Error play_record_review called without duration pointer\n"); - return -1; + SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_WARNING, "%s\n", "Error play_record_review called without duration pointer\n"); } if (!outsidecaller) @@ -16282,22 +16756,26 @@ static int play_record_review(struct ast_channel *chan, char *playfile, char *re } else { /* Otherwise 1 is to save the existing message */ ast_verb(3, "Saving message as is\n"); - if (!outsidecaller) + if (!outsidecaller) { + ast_trace(-1, "Renaming greeting '%s' to '%s'\n", tempfile, recordfile); ast_filerename(tempfile, recordfile, NULL); + } if (!forwardintro) { ast_stream_and_wait(chan, "vm-msgsaved", ""); } if (!outsidecaller) { /* Saves to IMAP server only if imapgreeting=yes */ - STORE(recordfile, vmu->mailbox, vmu->context, -1, chan, vmu, fmt, *duration, vms, flag, msg_id); - DISPOSE(recordfile, -1); + ast_trace(-1, "Saving greeting '%s'\n", recordfile); + SCOPE_CALL(-1, STORE, recordfile, vmu->mailbox, vmu->context, -1, chan, vmu, fmt, *duration, vms, flag, msg_id); + SCOPE_CALL(-1, DISPOSE, recordfile, -1); } cmd = 't'; - return res; + SCOPE_EXIT_RTN_VALUE(res, "Message saved to %s\n", recordfile); } case '2': /* Review */ ast_verb(3, "Reviewing the message\n"); + ast_trace(-1, "Reviewing '%s'\n", tempfile); cmd = ast_stream_and_wait(chan, tempfile, AST_DIGIT_ANY); break; case '3': @@ -16318,9 +16796,8 @@ static int play_record_review(struct ast_channel *chan, char *playfile, char *re } if (cmd == -1) { /* User has hung up, no options to give */ - ast_debug(1, "User hung up before message could be rerecorded\n"); ast_filedelete(tempfile, NULL); - return cmd; + SCOPE_EXIT_RTN_VALUE(cmd, "User hung up before message could be rerecorded. Deleted '%s'\n", tempfile); } recorded = 1; /* After an attempt has been made to record message, we have to take care of INTRO and beep for incoming messages, but not for greetings */ @@ -16328,6 +16805,7 @@ static int play_record_review(struct ast_channel *chan, char *playfile, char *re ast_channel_setoption(chan, AST_OPTION_RXGAIN, &record_gain, sizeof(record_gain), 0); if (ast_test_flag(vmu, VM_OPERATOR)) canceldtmf = "0"; + ast_trace(-1, "Recording '%s'\n", tempfile); cmd = ast_play_and_record_full(chan, playfile, tempfile, maxtime, fmt, duration, sound_duration, 0, silencethreshold, maxsilence, unlockdir, acceptdtmf, canceldtmf, 0, AST_RECORD_IF_EXISTS_OVERWRITE); if (strchr(canceldtmf, cmd)) { /* need this flag here to distinguish between pressing '0' during message recording or after */ @@ -16341,7 +16819,8 @@ static int play_record_review(struct ast_channel *chan, char *playfile, char *re /* user was recording a greeting and they hung up, so let's delete the recording. */ ast_filedelete(tempfile, NULL); } - return cmd; + SCOPE_EXIT_RTN_VALUE(cmd, "User hung up after recording. %s %s\n", + outsidecaller ? "Saved message " : "Deleted greeting \n", tempfile); } if (cmd == '0') { break; @@ -16417,10 +16896,12 @@ static int play_record_review(struct ast_channel *chan, char *playfile, char *re break; } if (msg_exists || recorded) { + ast_trace(-1, "Reviewing '%s'\n", tempfile); cmd = ast_play_and_wait(chan, "vm-saveoper"); if (!cmd) cmd = ast_waitfordigit(chan, 3000); if (cmd == '1') { + ast_trace(-1, "Saving '%s' to '%s'\n", tempfile, recordfile); ast_filerename(tempfile, recordfile, NULL); ast_play_and_wait(chan, "vm-msgsaved"); cmd = '0'; @@ -16432,9 +16913,10 @@ static int play_record_review(struct ast_channel *chan, char *playfile, char *re ast_play_and_wait(chan, "vm-msgsaved"); cmd = '0'; } else { + ast_trace(-1, "Deleting '%s'\n", tempfile); ast_play_and_wait(chan, "vm-deleted"); - DELETE(tempfile, -1, tempfile, vmu); - DISPOSE(tempfile, -1); + SCOPE_CALL(-1, DELETE, tempfile, -1, tempfile, vmu); + SCOPE_CALL(-1, DISPOSE, tempfile, -1); cmd = '0'; } } @@ -16443,8 +16925,9 @@ static int play_record_review(struct ast_channel *chan, char *playfile, char *re /* If the caller is an outside caller and the review option is enabled or it's forward intro allow them to review the message, but let the owner of the box review their OGM's */ - if (outsidecaller && !ast_test_flag(vmu, VM_REVIEW) && !forwardintro) - return cmd; + if (outsidecaller && !ast_test_flag(vmu, VM_REVIEW) && !forwardintro) { + SCOPE_EXIT_RTN_VALUE(cmd, "Done. Outside caller, review not set, no forwardintro\n"); + } if (msg_exists) { cmd = ast_play_and_wait(chan, "vm-review"); if (!cmd && outsidecaller && ast_test_flag(vmu, VM_MARK_URGENT)) { @@ -16481,13 +16964,14 @@ static int play_record_review(struct ast_channel *chan, char *playfile, char *re } if (!outsidecaller && (cmd == -1 || cmd == 't')) { /* Hang up or timeout, so delete the recording. */ + ast_trace(-1, "Deleting '%s' on hangup or timeout\n", tempfile); ast_filedelete(tempfile, NULL); } if (cmd != 't' && outsidecaller) ast_play_and_wait(chan, "vm-goodbye"); - return cmd; + SCOPE_EXIT_RTN_VALUE(cmd, "Done\n"); } static struct ast_vm_msg_snapshot *vm_msg_snapshot_alloc(void) diff --git a/configs/samples/voicemail.conf.sample b/configs/samples/voicemail.conf.sample index 4aaa68c4565..f35e4402fc7 100644 --- a/configs/samples/voicemail.conf.sample +++ b/configs/samples/voicemail.conf.sample @@ -138,12 +138,93 @@ maxlogins=3 ;fromstring=The Asterisk PBX ; Permit finding entries for forward/compose from the directory ;usedirectory=yes + +; ----------------------------------------------------------------------------- +; ODBC storage configuration +; ----------------------------------------------------------------------------- ; Voicemail can be stored in a database using the ODBC driver. -; The value of odbcstorage is the database connection configured -; in res_odbc.conf. -;odbcstorage=asterisk -; The default table for ODBC voicemail storage is voicemessages. -;odbctable=voicemessages +; +: Storage database: +; The value of odbcstorage is the database connection configured in +; res_odbc.conf. This may be different from the name of the ODBC DSN +; in /etc/odbc.ini which, in turn, may be different from the name of the +; actual database. If you used the voicemail.ini.sample alembic script +; located in contrib/ast-db-manage to create the database, the database +; name is 'voicemail' and the table name is 'voicemail_messages' so you'd +; need to ensure that /etc/odbc.ini has a DSN entry that points to that +; database and res_odbc.conf has an entry that points to that ODBC DSN. +; For historical compatibility, the default value of odbcstorage is +; actually 'asterisk' because originally voicemail messages were stored +; in the same database as the rest of the Asterisk configuration. + +;odbcstorage = voicemail + +; Storage table: +; The name of the table in which voicemail messages are stored. +; If you used the voicemail.ini.sample alembic script located in +; contrib/ast-db-manage to create the database, the table name +; is 'voicemail_messages'. For historical compatibility however, +; the default value of odbctable is 'voicemessages' because originally +; voicemail messages were stored in that table in the same database +; as the rest of the Asterisk configuration. + +;odbctable = voicemail_messages + +; Audio storage location: +; By default, voicemail and prompt audio files are stored as BLOBs +; in the database along with the message metadata. If you would +; prefer to store the audio files on disk and only store the message +; metadata in the database, set the following option to 'yes'. +; This can be advantageous in some scenarios, such as when the +; database is on a separate server from the Asterisk server and +; network latency and size is a concern or when the database is +; not well-suited for storing large binary objects. It can also +; be useful when you want to use the same voicemail storage +; configuration for multiple Asterisk servers. In this situation +; you can have all the servers use a single shared network file +; system to store the audio files and use the same database for fast +; access to the message metadata. + +; If you set this option to "yes", new messages and greetings will +; have their audio kept on disk but the audio for existing messages +; and greetings will remain in the database until the next time +; they are played. At that time, the audio will be moved to disk +; and erased from the database. + +; If you set this option to "no" after you've already stored messages +; or greetings with it set to "yes", new messages and greetings will +; have their audio stored in the database but the audio for existing +; messages and greetings will remain on disk until the next time they +; are played. At that time, the audio will be moved to the database +; and erased from the disk. + +; WARNING: Before changing this option from "yes" to "no" or vice +; versa make sure you have complete backups of your voicemail +; database and audio files. + +; WARNING: If you set this option to "yes" and then later set it +; to "no", you must ensure that the audio files are not deleted +; from the disk until you are certain that they have been moved +; to the database. If you delete the audio files before they are +; moved to the database, the messages will be lost. + +; WARNING: YOU MUST NOT DOWNGRADE ASTERISK TO A VERSION THAT DOESN'T +; UNDERSTAND THIS OPTION if you've set this option to "yes" previously +; and there are audio files stored on disk. If those files are +; accessed by a version of Asterisk that doesn't understand this +; option, the files will be corrupted and the messages will be lost. +; If you do need to downgrade in this situation, you'll have to write +; your own script to move the audio files back into the 'recording' +; column of the database table. If you record multiple formats, +; the file to write to the 'recording' column will be the first format +; listed in the 'format' option in this config file. If the first +; format is 'wav49', the file to add to the database will be the one +; with the 'WAV' extension. + +; odbc_audio_on_disk = no + +; ----------------------------------------------------------------------------- + ; ; Change the from, body and/or subject, variables: ; VM_NAME, VM_DUR, VM_MSGNUM, VM_MAILBOX, VM_CALLERID, VM_CIDNUM, diff --git a/main/app.c b/main/app.c index 5d3d78867b9..f656d2e7d54 100644 --- a/main/app.c +++ b/main/app.c @@ -1794,7 +1794,11 @@ static int global_maxsilence = 0; * \retval 't' Recording ended from the message exceeding the maximum duration, or via DTMF in prepend mode * \retval dtmfchar Recording ended via the return value's DTMF character for either cancel or accept. */ -static int __ast_play_and_record(struct ast_channel *chan, const char *playfile, const char *recordfile, int maxtime, const char *fmt, int *duration, int *sound_duration, int beep, int silencethreshold, int maxsilence, const char *path, int prepend, const char *acceptdtmf, const char *canceldtmf, int skip_confirmation_sound, enum ast_record_if_exists if_exists) +static int __ast_play_and_record(struct ast_channel *chan, const char *playfile, + const char *recordfile, int maxtime, const char *fmt, int *duration, + int *sound_duration, int beep, int silencethreshold, int maxsilence, + const char *path, int prepend, const char *acceptdtmf, const char *canceldtmf, + int skip_confirmation_sound, enum ast_record_if_exists if_exists) { int d = 0; char *fmts; @@ -1812,6 +1816,8 @@ static int __ast_play_and_record(struct ast_channel *chan, const char *playfile, struct ast_silence_generator *silgen = NULL; char prependfile[PATH_MAX]; int ioflags; /* IO flags for writing output file */ + SCOPE_ENTER(3, "%s: play: '%s' record: '%s' path: '%s' prepend: %d\n", + ast_channel_name(chan), playfile, recordfile, path, prepend); ioflags = O_CREAT|O_WRONLY; @@ -1849,19 +1855,22 @@ static int __ast_play_and_record(struct ast_channel *chan, const char *playfile, if (playfile || beep) { if (!beep) { + ast_trace(-1, "Playing '%s' to '%s'\n", playfile, ast_channel_name(chan)); d = ast_play_and_wait(chan, playfile); } if (d > -1) { + ast_trace(-1, "Playing 'beep' to '%s'\n", ast_channel_name(chan)); d = ast_stream_and_wait(chan, "beep", ""); } if (d < 0) { - return -1; + SCOPE_EXIT_RTN_VALUE(-1, "Failed to play. RC: %d\n", d); } } if (prepend) { ast_copy_string(prependfile, recordfile, sizeof(prependfile)); strncat(prependfile, "-prepend", sizeof(prependfile) - strlen(prependfile) - 1); + ast_trace(-1, "Prepending to '%s'\n", prependfile); } fmts = ast_strdupa(fmt); @@ -1887,7 +1896,7 @@ static int __ast_play_and_record(struct ast_channel *chan, const char *playfile, end = start = time(NULL); /* pre-initialize end to be same as start in case we never get into loop */ for (x = 0; x < fmtcnt; x++) { others[x] = ast_writefile(prepend ? prependfile : recordfile, sfmt[x], comment, ioflags, 0, AST_FILE_MODE); - ast_verb(3, "x=%d, open writing: %s format: %s, %p\n", x, prepend ? prependfile : recordfile, sfmt[x], others[x]); + ast_trace(-1, "x=%d, open writing: %s format: %s, %p\n", x, prepend ? prependfile : recordfile, sfmt[x], others[x]); if (!others[x]) { break; @@ -2178,7 +2187,8 @@ static int __ast_play_and_record(struct ast_channel *chan, const char *playfile, ast_closestream(others[x]); ast_closestream(realfiles[x]); ast_filerename(prependfile, recordfile, sfmt[x]); - ast_verb(4, "Recording Format: sfmts=%s, prependfile %s, recordfile %s\n", sfmt[x], prependfile, recordfile); + ast_trace(-1, "Recording Format: sfmts=%s, prependfile %s, recordfile %s\n", sfmt[x], prependfile, recordfile); + ast_trace(-1, "Deleting the prepend file %s.%s\n", recordfile, sfmt[x]); ast_filedelete(prependfile, sfmt[x]); } } else { @@ -2200,7 +2210,7 @@ static int __ast_play_and_record(struct ast_channel *chan, const char *playfile, if (sildet) { ast_dsp_free(sildet); } - return res; + SCOPE_EXIT_RTN_VALUE(res, "Done. RC: %d\n", res); } static const char default_acceptdtmf[] = "#";