From fb5690ce4b9ff896a56fe9b9eb9eeed1a2b5f028 Mon Sep 17 00:00:00 2001 From: Matthew Jordan <mjordan@digium.com> Date: Wed, 28 May 2014 22:54:12 +0000 Subject: [PATCH] Logger/CLI/etc.: Fix some aesthetic issues; reduce chatty verbose messages This patch addresses some aesthetic issues in Asterisk. These are all just minor tweaks to improve the look of the CLI when used in a variety of settings. Specifically: * A number of chatty verbose messages were removed or demoted to DEBUG messages. Verbose messages with a verbosity level of 5 or higher were - if kept as verbose messages - demoted to level 4. Several messages that were emitted at verbose level 3 were demoted to 4, as announcement of dialplan applications being executed occur at level 3 (and so the effects of those applications should generally be less). * Some verbose messages that only appear when their respective 'debug' options are enabled were bumped up to always be displayed. * Prefix/timestamping of verbose messages were moved to the verboser handlers. This was done to prevent duplication of prefixes when the timestamp option (-T) is used with the CLI. * Verbose magic is removed from messages before being emitted to non-verboser handlers. This prevents the magic in multi-line verbose messages (such as SIP debug traces or the output of DumpChan) from being written to files. * _Slightly_ better support for the "light background" option (-W) was added. This includes using ast_term_quit in the output of XML documentation help, as well as changing the "Asterisk Ready" prompt to bright green on the default background (which stands a better chance of being displayed properly than bright white). Review: https://reviewboard.asterisk.org/r/3547/ git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@414798 65c4cc65-6c06-0410-ace0-fbb531ad65f3 --- apps/app_mixmonitor.c | 2 +- apps/app_voicemail.c | 2 +- apps/app_waitforsilence.c | 2 +- bridges/bridge_builtin_features.c | 28 +++++++------- cdr/cdr_adaptive_odbc.c | 8 ++-- cdr/cdr_odbc.c | 5 --- cdr/cdr_pgsql.c | 5 +-- cdr/cdr_sqlite3_custom.c | 2 +- cel/cel_odbc.c | 3 +- cel/cel_pgsql.c | 3 +- channels/chan_unistim.c | 12 +++--- include/asterisk/logger.h | 9 +++++ main/asterisk.c | 45 +++++++++++++---------- main/bridge.c | 4 +- main/config_options.c | 2 +- main/loader.c | 19 +++------- main/logger.c | 59 ++++++++++++++++++++---------- main/optional_api.c | 10 ----- main/pbx.c | 5 +-- main/xmldoc.c | 2 +- res/parking/parking_applications.c | 2 +- res/res_config_curl.c | 4 +- res/res_config_odbc.c | 3 +- res/res_config_pgsql.c | 3 +- res/res_fax.c | 2 +- res/res_jabber.c | 2 +- res/res_odbc.c | 2 +- 27 files changed, 124 insertions(+), 121 deletions(-) diff --git a/apps/app_mixmonitor.c b/apps/app_mixmonitor.c index 6a2a0fcece..8013c8c684 100644 --- a/apps/app_mixmonitor.c +++ b/apps/app_mixmonitor.c @@ -502,7 +502,7 @@ static void add_vm_recipients_from_string(struct mixmonitor *mixmonitor, const c ast_copy_string(recipient->folder, cur_folder, sizeof(recipient->folder)); /* Add to list */ - ast_verb(5, "Adding %s@%s to recipient list\n", recipient->mailbox, recipient->context); + ast_verb(4, "Adding %s@%s to recipient list\n", recipient->mailbox, recipient->context); AST_LIST_INSERT_HEAD(&mixmonitor->recipient_list, recipient, list); } else { ast_log(LOG_ERROR, "Failed to properly parse extension and/or context from element %d of recipient string: %s\n", elements_processed, vm_recipients); diff --git a/apps/app_voicemail.c b/apps/app_voicemail.c index cb85c5be9f..891d233605 100644 --- a/apps/app_voicemail.c +++ b/apps/app_voicemail.c @@ -7557,7 +7557,7 @@ static int get_folder(struct ast_channel *chan, int start) if (ast_fileexists(fn, NULL, NULL)) { d = vm_play_folder_name(chan, fn); } else { - ast_verb(1, "failed to find %s\n", fn); + ast_verb(4, "Failed to find file %s; falling back to INBOX\n", fn); d = vm_play_folder_name(chan, "vm-INBOX"); } } else { diff --git a/apps/app_waitforsilence.c b/apps/app_waitforsilence.c index f79247274f..53870df30f 100644 --- a/apps/app_waitforsilence.c +++ b/apps/app_waitforsilence.c @@ -179,7 +179,7 @@ static int do_waiting(struct ast_channel *chan, int timereqd, time_t waitstart, ast_frfree(f); } - ast_verb(6, "Got %dms %s < %dms required\n", dsptime, wait_for_silence ? "silence" : "noise", timereqd); + ast_debug(1, "Got %dms %s < %dms required\n", dsptime, wait_for_silence ? "silence" : "noise", timereqd); if (dsptime >= timereqd) { ast_verb(3, "Exiting with %dms %s >= %dms required\n", dsptime, wait_for_silence ? "silence" : "noise", timereqd); diff --git a/bridges/bridge_builtin_features.c b/bridges/bridge_builtin_features.c index b300052570..503de4c33c 100644 --- a/bridges/bridge_builtin_features.c +++ b/bridges/bridge_builtin_features.c @@ -106,12 +106,12 @@ static enum set_touch_variables_res set_touch_variables(struct ast_channel *chan static void stop_automonitor(struct ast_bridge_channel *bridge_channel, struct ast_channel *peer_chan, struct ast_features_general_config *features_cfg, const char *stop_message) { - ast_verb(3, "AutoMonitor used to stop recording call.\n"); + ast_verb(4, "AutoMonitor used to stop recording call.\n"); ast_channel_lock(peer_chan); if (ast_channel_monitor(peer_chan)) { if (ast_channel_monitor(peer_chan)->stop(peer_chan, 1)) { - ast_verb(3, "Cannot stop AutoMonitor for %s\n", ast_channel_name(bridge_channel->chan)); + ast_verb(4, "Cannot stop AutoMonitor for %s\n", ast_channel_name(bridge_channel->chan)); if (features_cfg && !(ast_strlen_zero(features_cfg->recordingfailsound))) { ast_bridge_channel_queue_playfile(bridge_channel, NULL, features_cfg->recordingfailsound, NULL); } @@ -194,10 +194,10 @@ static void start_automonitor(struct ast_bridge_channel *bridge_channel, struct } } - ast_verb(3, "AutoMonitor used to record call. Filename: %s\n", touch_filename); + ast_verb(4, "AutoMonitor used to record call. Filename: %s\n", touch_filename); if (ast_monitor_start(peer_chan, touch_format, touch_filename, 1, X_REC_IN | X_REC_OUT, NULL)) { - ast_verb(3, "automon feature was tried by '%s' but monitor failed to start.\n", + ast_verb(4, "AutoMonitor feature was tried by '%s' but monitor failed to start.\n", ast_channel_name(bridge_channel->chan)); return; } @@ -232,7 +232,7 @@ static int feature_automonitor(struct ast_bridge_channel *bridge_channel, void * ast_bridge_unlock(bridge_channel->bridge); if (!peer_chan) { - ast_verb(3, "Cannot start AutoMonitor for %s - can not determine peer in bridge.\n", + ast_verb(4, "Cannot start AutoMonitor for %s - can not determine peer in bridge.\n", ast_channel_name(bridge_channel->chan)); if (features_cfg && !ast_strlen_zero(features_cfg->recordingfailsound)) { ast_bridge_channel_queue_playfile(bridge_channel, NULL, features_cfg->recordingfailsound, NULL); @@ -263,14 +263,14 @@ static int feature_automonitor(struct ast_bridge_channel *bridge_channel, void * start_automonitor(bridge_channel, peer_chan, features_cfg, start_message); return 0; } - ast_verb(3, "AutoMonitor already recording call.\n"); + ast_verb(4, "AutoMonitor already recording call.\n"); break; case AUTO_MONITOR_STOP: if (is_monitoring) { stop_automonitor(bridge_channel, peer_chan, features_cfg, stop_message); return 0; } - ast_verb(3, "AutoMonitor already not recording call.\n"); + ast_verb(4, "AutoMonitor already stopped on call.\n"); break; } @@ -295,10 +295,10 @@ static int feature_automonitor(struct ast_bridge_channel *bridge_channel, void * static void stop_automixmonitor(struct ast_bridge_channel *bridge_channel, struct ast_channel *peer_chan, struct ast_features_general_config *features_cfg, const char *stop_message) { - ast_verb(3, "AutoMixMonitor used to stop recording call.\n"); + ast_verb(4, "AutoMixMonitor used to stop recording call.\n"); if (ast_stop_mixmonitor(peer_chan, NULL)) { - ast_verb(3, "Failed to stop Mixmonitor for %s.\n", ast_channel_name(bridge_channel->chan)); + ast_verb(4, "Failed to stop AutoMixMonitor for %s.\n", ast_channel_name(bridge_channel->chan)); if (features_cfg && !(ast_strlen_zero(features_cfg->recordingfailsound))) { ast_bridge_channel_queue_playfile(bridge_channel, NULL, features_cfg->recordingfailsound, NULL); } @@ -375,10 +375,10 @@ static void start_automixmonitor(struct ast_bridge_channel *bridge_channel, stru } } - ast_verb(3, "AutoMixMonitor used to record call. Filename: %s\n", touch_filename); + ast_verb(4, "AutoMixMonitor used to record call. Filename: %s\n", touch_filename); if (ast_start_mixmonitor(peer_chan, touch_filename, "b")) { - ast_verb(3, "automixmon feature was tried by '%s' but mixmonitor failed to start.\n", + ast_verb(4, "AutoMixMonitor feature was tried by '%s' but MixMonitor failed to start.\n", ast_channel_name(bridge_channel->chan)); if (features_cfg && !ast_strlen_zero(features_cfg->recordingfailsound)) { @@ -418,7 +418,7 @@ static int feature_automixmonitor(struct ast_bridge_channel *bridge_channel, voi ast_bridge_unlock(bridge_channel->bridge); if (!peer_chan) { - ast_verb(3, "Cannot do AutoMixMonitor for %s - cannot determine peer in bridge.\n", + ast_verb(4, "Cannot start AutoMixMonitor for %s - cannot determine peer in bridge.\n", ast_channel_name(bridge_channel->chan)); if (features_cfg && !ast_strlen_zero(features_cfg->recordingfailsound)) { ast_bridge_channel_queue_playfile(bridge_channel, NULL, features_cfg->recordingfailsound, NULL); @@ -450,14 +450,14 @@ static int feature_automixmonitor(struct ast_bridge_channel *bridge_channel, voi start_automixmonitor(bridge_channel, peer_chan, features_cfg, start_message); return 0; } - ast_verb(3, "AutoMixMonitor already recording call.\n"); + ast_verb(4, "AutoMixMonitor already recording call.\n"); break; case AUTO_MONITOR_STOP: if (is_monitoring) { stop_automixmonitor(bridge_channel, peer_chan, features_cfg, stop_message); return 0; } - ast_verb(3, "AutoMixMonitor already not recording call.\n"); + ast_verb(4, "AutoMixMonitor already stopped on call.\n"); break; } diff --git a/cdr/cdr_adaptive_odbc.c b/cdr/cdr_adaptive_odbc.c index a5a8b8588a..72c26198f2 100644 --- a/cdr/cdr_adaptive_odbc.c +++ b/cdr/cdr_adaptive_odbc.c @@ -196,7 +196,7 @@ static int load_config(void) ast_trim_blanks(cdrvar); } - ast_verb(3, "Found filter %s'%s' for cdr variable %s in %s@%s\n", negate ? "!" : "", var->value, cdrvar, tableptr->table, tableptr->connection); + ast_verb(3, "Found filter %s'%s' for CDR variable %s in %s@%s\n", negate ? "!" : "", var->value, cdrvar, tableptr->table, tableptr->connection); entry = ast_calloc(sizeof(char), sizeof(*entry) + strlen(cdrvar) + 1 + strlen(var->value) + 1); if (!entry) { @@ -281,7 +281,7 @@ static int load_config(void) if (entry->octetlen == 0) entry->octetlen = entry->size; - ast_verb(10, "Found %s column with type %hd with len %ld, octetlen %ld, and numlen (%hd,%hd)\n", entry->name, entry->type, (long) entry->size, (long) entry->octetlen, entry->decimals, entry->radix); + ast_verb(4, "Found %s column with type %hd with len %ld, octetlen %ld, and numlen (%hd,%hd)\n", entry->name, entry->type, (long) entry->size, (long) entry->octetlen, entry->decimals, entry->radix); /* Insert column info into column list */ AST_LIST_INSERT_TAIL(&(tableptr->columns), entry, list); res = 0; @@ -723,7 +723,7 @@ static int odbc_log(struct ast_cdr *cdr) } else if (entry->filtervalue && ((!entry->negatefiltervalue && entry->filtervalue[0] != '\0') || (entry->negatefiltervalue && entry->filtervalue[0] == '\0'))) { - ast_verb(4, "CDR column '%s' was not set and does not match filter of" + ast_log(AST_LOG_WARNING, "CDR column '%s' was not set and does not match filter of" " %s'%s'. Cancelling this CDR.\n", entry->cdrname, entry->negatefiltervalue ? "!" : "", entry->filtervalue); @@ -737,7 +737,7 @@ static int odbc_log(struct ast_cdr *cdr) ast_str_append(&sql2, 0, ")"); ast_str_append(&sql, 0, "%s", ast_str_buffer(sql2)); - ast_verb(11, "[%s]\n", ast_str_buffer(sql)); + ast_debug(3, "Executing [%s]\n", ast_str_buffer(sql)); stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, ast_str_buffer(sql)); if (stmt) { diff --git a/cdr/cdr_odbc.c b/cdr/cdr_odbc.c index be07a8a56b..2e86a06c40 100644 --- a/cdr/cdr_odbc.c +++ b/cdr/cdr_odbc.c @@ -252,9 +252,6 @@ static int odbc_load_module(int reload) break; } - ast_verb(3, "cdr_odbc: dsn is %s\n", dsn); - ast_verb(3, "cdr_odbc: table is %s\n", table); - if (!ast_test_flag(&config, CONFIG_REGISTERED)) { res = ast_cdr_register(name, ast_module_info->description, odbc_log); if (res) { @@ -290,11 +287,9 @@ static int unload_module(void) } if (dsn) { - ast_verb(11, "cdr_odbc: free dsn\n"); ast_free(dsn); } if (table) { - ast_verb(11, "cdr_odbc: free table\n"); ast_free(table); } diff --git a/cdr/cdr_pgsql.c b/cdr/cdr_pgsql.c index 6ac3897884..8322da9b55 100644 --- a/cdr/cdr_pgsql.c +++ b/cdr/cdr_pgsql.c @@ -348,9 +348,8 @@ static int pgsql_log(struct ast_cdr *cdr) LENGTHEN_BUF1(ast_str_strlen(sql2) + 2); AST_RWLIST_UNLOCK(&psql_columns); ast_str_append(&sql, 0, ")%s)", ast_str_buffer(sql2)); - ast_verb(11, "[%s]\n", ast_str_buffer(sql)); - ast_debug(2, "inserting a CDR record.\n"); + ast_debug(3, "Inserting a CDR record: [%s]\n", ast_str_buffer(sql)); /* Test to be sure we're still connected... */ /* If we're connected, and connection is working, good. */ @@ -691,7 +690,7 @@ static int config_module(int reload) /* For varchar columns, the maximum length is encoded in a different field */ flen = PQgetvalue(result, i, 5); } - ast_verb(4, "Found column '%s' of type '%s'\n", fname, ftype); + cur = ast_calloc(1, sizeof(*cur) + strlen(fname) + strlen(ftype) + 2); if (cur) { sscanf(flen, "%30d", &cur->len); diff --git a/cdr/cdr_sqlite3_custom.c b/cdr/cdr_sqlite3_custom.c index 83dac6a5d6..435f4b37e3 100644 --- a/cdr/cdr_sqlite3_custom.c +++ b/cdr/cdr_sqlite3_custom.c @@ -197,7 +197,7 @@ static int load_config(int reload) return -1; } - ast_verb(3, "cdr_sqlite3_custom: Logging CDR records to table '%s' in 'master.db'\n", table); + ast_verb(4, "cdr_sqlite3_custom: Logging CDR records to table '%s' in 'master.db'\n", table); ast_config_destroy(cfg); diff --git a/cel/cel_odbc.c b/cel/cel_odbc.c index 87036bbf6b..035857b685 100644 --- a/cel/cel_odbc.c +++ b/cel/cel_odbc.c @@ -761,8 +761,7 @@ static void odbc_log(struct ast_event *event) ast_str_append(&sql2, 0, ")"); ast_str_append(&sql, 0, "%s", ast_str_buffer(sql2)); - ast_verb(11, "[%s]\n", ast_str_buffer(sql)); - + ast_debug(3, "Executing SQL statement: [%s]\n", ast_str_buffer(sql)); stmt = ast_odbc_prepare_and_execute(obj, generic_prepare, ast_str_buffer(sql)); if (stmt) { SQLRowCount(stmt, &rows); diff --git a/cel/cel_pgsql.c b/cel/cel_pgsql.c index 7b1bd09edb..cd50af0e51 100644 --- a/cel/cel_pgsql.c +++ b/cel/cel_pgsql.c @@ -288,9 +288,8 @@ static void pgsql_log(struct ast_event *event) AST_RWLIST_UNLOCK(&psql_columns); LENGTHEN_BUF1(ast_str_strlen(sql2) + 2); ast_str_append(&sql, 0, ")%s)", ast_str_buffer(sql2)); - ast_verb(11, "[%s]\n", ast_str_buffer(sql)); - ast_debug(2, "inserting a CEL record.\n"); + ast_debug(3, "Inserting a CEL record: [%s].\n", ast_str_buffer(sql)); /* Test to be sure we're still connected... */ /* If we're connected, and connection is working, good. */ /* Otherwise, attempt reconnect. If it fails... sorry... */ diff --git a/channels/chan_unistim.c b/channels/chan_unistim.c index 6762db3915..7525f3921b 100644 --- a/channels/chan_unistim.c +++ b/channels/chan_unistim.c @@ -973,7 +973,7 @@ static void send_client(int size, const unsigned char *data, struct unistimsessi /*#ifdef DUMP_PACKET */ if (unistimdebug) { - ast_verb(6, "Sending datas with seq #0x%.4x Using slot #%d :\n", (unsigned)pte->seq_server, buf_pos); + ast_verb(0, "Sending datas with seq #0x%.4x Using slot #%d :\n", (unsigned)pte->seq_server, buf_pos); } /*#endif */ send_raw_client(pte->wsabufsend[buf_pos].len, pte->wsabufsend[buf_pos].buf, &(pte->sin), @@ -986,7 +986,7 @@ static void send_ping(struct unistimsession *pte) { BUFFSEND; if (unistimdebug) { - ast_verb(6, "Sending ping\n"); + ast_verb(0, "Sending ping\n"); } pte->tick_next_ping = get_tick_count() + unistim_keepalive; memcpy(buffsend + SIZE_HEADER, packet_send_ping, sizeof(packet_send_ping)); @@ -1084,7 +1084,7 @@ static void check_send_queue(struct unistimsession *pte) /* Check if our send queue contained only one element */ if (pte->last_buf_available == 1) { if (unistimdebug) { - ast_verb(6, "Our single packet was ACKed.\n"); + ast_verb(0, "Our single packet was ACKed.\n"); } pte->last_buf_available--; set_ping_timer(pte); @@ -1093,14 +1093,14 @@ static void check_send_queue(struct unistimsession *pte) /* Check if this ACK catch up our latest packet */ else if (pte->last_seq_ack + 1 == pte->seq_server + 1) { if (unistimdebug) { - ast_verb(6, "Our send queue is completely ACKed.\n"); + ast_verb(0, "Our send queue is completely ACKed.\n"); } pte->last_buf_available = 0; /* Purge the send queue */ set_ping_timer(pte); return; } if (unistimdebug) { - ast_verb(6, "We still have packets in our send queue\n"); + ast_verb(0, "We still have packets in our send queue\n"); } return; } @@ -4659,7 +4659,7 @@ static void parsing(int size, unsigned char *buf, struct unistimsession *pte, if (buf[4] == 1) { ast_mutex_lock(&pte->lock); if (unistimdebug) { - ast_verb(6, "ACK received for packet #0x%.4x\n", (unsigned)seq); + ast_verb(0, "ACK received for packet #0x%.4x\n", (unsigned)seq); } pte->nb_retransmit = 0; diff --git a/include/asterisk/logger.h b/include/asterisk/logger.h index eda50351ca..bd9c9c7bdf 100644 --- a/include/asterisk/logger.h +++ b/include/asterisk/logger.h @@ -262,6 +262,15 @@ int ast_logger_register_level(const char *name); */ void ast_logger_unregister_level(const char *name); +/*! + * \brief Get the logger configured date format + * + * \retval The date format string + * + * \since 13.0.0 + */ +const char *ast_logger_get_dateformat(void); + /*! * \brief factory function to create a new uniquely identifying callid. * diff --git a/main/asterisk.c b/main/asterisk.c index a3bb88198a..213828c039 100644 --- a/main/asterisk.c +++ b/main/asterisk.c @@ -2068,13 +2068,14 @@ static void __remote_quit_handler(int num) sig_flags.need_quit = 1; } -static const char *fix_header(char *outbuf, int maxout, const char *s, char level) +static void set_header(char *outbuf, int maxout, char level) { const char *cmp; + char date[40]; switch (level) { - case 0: *outbuf = '\0'; - return s; + case 0: cmp = NULL; + break; case 1: cmp = VERBOSE_PREFIX_1; break; case 2: cmp = VERBOSE_PREFIX_2; @@ -2085,12 +2086,20 @@ static const char *fix_header(char *outbuf, int maxout, const char *s, char leve break; } - if (!strncmp(s, cmp, strlen(cmp))) { - s += strlen(cmp); + if (ast_opt_timestamp) { + struct ast_tm tm; + struct timeval now = ast_tvnow(); + ast_localtime(&now, &tm, NULL); + ast_strftime(date, sizeof(date), ast_logger_get_dateformat(), &tm); } - term_color(outbuf, cmp, COLOR_GRAY, 0, maxout); - return s; + snprintf(outbuf, maxout, "%s%s%s%s%s%s", + ast_opt_timestamp ? "[" : "", + ast_opt_timestamp ? date : "", + ast_opt_timestamp ? "] " : "", + cmp ? ast_term_color(COLOR_GRAY, 0) : "", + cmp ? cmp : "", + cmp ? ast_term_reset() : ""); } struct console_state_data { @@ -2118,16 +2127,15 @@ static int console_print(const char *s, int local) do { if (VERBOSE_HASMAGIC(s)) { + /* always use the given line's level, otherwise we'll use the last line's level */ state->verbose_line_level = VERBOSE_MAGIC2LEVEL(s); + /* move past magic */ s++; - if (local) { - s = fix_header(prefix, sizeof(prefix), s, - state->verbose_line_level); - } + set_header(prefix, sizeof(prefix), state->verbose_line_level); } else { *prefix = '\0'; } @@ -2149,7 +2157,7 @@ static int console_print(const char *s, int local) continue; } - if (local && !ast_strlen_zero(prefix)) { + if (!ast_strlen_zero(prefix)) { fputs(prefix, stdout); } @@ -2572,8 +2580,6 @@ static char *show_license(struct ast_cli_entry *e, int cmd, struct ast_cli_args #define ASTERISK_PROMPT "*CLI> " -#define ASTERISK_PROMPT2 "%s*CLI> " - /*! * \brief Shutdown Asterisk CLI commands. * @@ -2841,10 +2847,10 @@ static char *cli_prompt(EditLine *editline) /* Force colors back to normal at end */ ast_term_color_code(&prompt, 0, 0); } - } else if (remotehostname) { - ast_str_set(&prompt, 0, ASTERISK_PROMPT2, remotehostname); } else { - ast_str_set(&prompt, 0, "%s", ASTERISK_PROMPT); + ast_str_set(&prompt, 0, "%s%s", + remotehostname ? remotehostname : "", + ASTERISK_PROMPT); } return ast_str_buffer(prompt); @@ -4552,9 +4558,6 @@ int main(int argc, char *argv[]) dnsmgr_start_refresh(); - /* We might have the option of showing a console, but for now just - do nothing... */ - ast_verb(0, COLORIZE_FMT "\n", COLORIZE(COLOR_BRWHITE, COLOR_BLACK, "Asterisk Ready.")); if (ast_opt_no_fork) { consolethread = pthread_self(); } @@ -4581,6 +4584,8 @@ int main(int argc, char *argv[]) run_startup_commands(); + ast_verb(0, COLORIZE_FMT "\n", COLORIZE(COLOR_BRGREEN, 0, "Asterisk Ready.")); + if (ast_opt_console) { /* Console stuff now... */ /* Register our quit function */ diff --git a/main/bridge.c b/main/bridge.c index fa4e3c699c..dd6861785a 100644 --- a/main/bridge.c +++ b/main/bridge.c @@ -2541,7 +2541,7 @@ static int try_swap_optimize_out(struct ast_bridge *chan_bridge, id = ast_atomic_fetchadd_int((int *) &optimization_id, +1); - ast_verb(3, "Move-swap optimizing %s <-- %s.\n", + ast_verb(4, "Move-swap optimizing %s <-- %s.\n", ast_channel_name(dst_bridge_channel->chan), ast_channel_name(other->chan)); @@ -2658,7 +2658,7 @@ static int try_merge_optimize_out(struct ast_bridge *chan_bridge, return 0; } - ast_verb(3, "Merge optimizing %s -- %s out.\n", + ast_verb(4, "Merge optimizing %s -- %s out.\n", ast_channel_name(chan_bridge_channel->chan), ast_channel_name(peer_bridge_channel->chan)); diff --git a/main/config_options.c b/main/config_options.c index a52a9da250..ae40c62897 100644 --- a/main/config_options.c +++ b/main/config_options.c @@ -1191,7 +1191,7 @@ static void cli_show_module_options(struct ast_cli_args *a) ast_cli(a->fd, "\n"); } term_color(option_name, tmp->ref, COLOR_MAGENTA, COLOR_BLACK, sizeof(option_name)); - ast_cli(a->fd, "[%s%s]\n", option_name, term_end()); + ast_cli(a->fd, "[%s%s]\n", option_name, ast_term_reset()); if (ast_str_strlen(tmp->syntax)) { ast_cli(a->fd, "%s\n", ast_xmldoc_printable(ast_str_buffer(tmp->syntax), 1)); } diff --git a/main/loader.c b/main/loader.c index e40cbf3690..d4e94a6228 100644 --- a/main/loader.c +++ b/main/loader.c @@ -185,7 +185,7 @@ void ast_module_register(const struct ast_module_info *info) mod = resource_being_loaded; } - ast_verb(5, "Registering module %s\n", info->name); + ast_debug(5, "Registering module %s\n", info->name); mod->info = info; AST_LIST_HEAD_INIT(&mod->users); @@ -232,7 +232,7 @@ void ast_module_unregister(const struct ast_module_info *info) AST_LIST_UNLOCK(&module_list); if (mod) { - ast_verb(5, "Unregistering module %s\n", info->name); + ast_debug(5, "Unregistering module %s\n", info->name); AST_LIST_HEAD_DESTROY(&mod->users); ast_free(mod); } @@ -440,20 +440,16 @@ static int is_module_loaded(const char *resource_name) char fn[PATH_MAX] = ""; void *lib; - ast_verb(10, "Checking if %s is loaded\n", resource_name); - snprintf(fn, sizeof(fn), "%s/%s", ast_config_AST_MODULE_DIR, resource_name); lib = dlopen(fn, RTLD_LAZY | RTLD_NOLOAD); if (lib) { - ast_verb(10, " %s loaded\n", resource_name); logged_dlclose(resource_name, lib); return 1; } - ast_verb(10, " %s not loaded\n", resource_name); return 0; } #endif @@ -843,7 +839,7 @@ enum ast_module_reload_result ast_module_reload(const char *name) } if (ast_mutex_trylock(&reloadlock)) { - ast_verbose("The previous reload command didn't finish yet\n"); + ast_verb(3, "The previous reload command didn't finish yet\n"); res = AST_MODULE_RELOAD_IN_PROGRESS; goto module_reload_exit; } @@ -859,7 +855,7 @@ enum ast_module_reload_result ast_module_reload(const char *name) } } if (res != AST_LOCK_SUCCESS) { - ast_verbose("Cannot grab lock on %s\n", ast_config_AST_CONFIG_DIR); + ast_log(AST_LOG_WARNING, "Cannot grab lock on %s\n", ast_config_AST_CONFIG_DIR); ast_mutex_unlock(&reloadlock); res = AST_MODULE_RELOAD_ERROR; goto module_reload_exit; @@ -977,12 +973,7 @@ static enum ast_module_load_result start_resource(struct ast_module *mod) switch (res) { case AST_MODULE_LOAD_SUCCESS: if (!ast_fully_booted) { - ast_verb(1, "%s => (%s)\n", mod->resource, term_color(tmp, mod->info->description, COLOR_BROWN, COLOR_BLACK, sizeof(tmp))); - if (ast_opt_console && !option_verbose) { - /* This never looks good on anything but the root console, so - * it's best not to try to funnel it through the logger. */ - fprintf(stdout, "."); - } + ast_verb(2, "%s => (%s)\n", mod->resource, term_color(tmp, mod->info->description, COLOR_BROWN, COLOR_BLACK, sizeof(tmp))); } else { ast_verb(1, "Loaded %s => (%s)\n", mod->resource, mod->info->description); } diff --git a/main/logger.c b/main/logger.c index 2c0f3f4a30..16a044a6e9 100644 --- a/main/logger.c +++ b/main/logger.c @@ -235,6 +235,7 @@ static const int colors[NUMLOGLEVELS] = { }; AST_THREADSTORAGE(verbose_buf); +AST_THREADSTORAGE(verbose_build_buf); #define VERBOSE_BUF_INIT_SIZE 256 AST_THREADSTORAGE(log_buf); @@ -1171,25 +1172,50 @@ static void ast_log_vsyslog(struct logmsg *msg) syslog(syslog_level, "%s", buf); } +static char *logger_strip_verbose_magic(const char *message, int level) +{ + char *p; + char *stripped_message = ast_strdup(message); + char magic = -(level + 1); + + if (!stripped_message) { + return NULL; + } + + do { + p = strchr(stripped_message, (char)magic); + if (p) { + *p++ = ' '; + } + } while (p && *p); + + return stripped_message; +} + /*! \brief Print a normal log message to the channels */ static void logger_print_normal(struct logmsg *logmsg) { struct logchannel *chan = NULL; char buf[BUFSIZ]; struct verb *v = NULL; + char *tmpmsg; int level = 0; if (logmsg->level == __LOG_VERBOSE) { - char *tmpmsg = ast_strdupa(logmsg->message + 1); - - level = VERBOSE_MAGIC2LEVEL(logmsg->message); /* Iterate through the list of verbosers and pass them the log message string */ AST_RWLIST_RDLOCK(&verbosers); AST_RWLIST_TRAVERSE(&verbosers, v, list) v->verboser(logmsg->message); AST_RWLIST_UNLOCK(&verbosers); - ast_string_field_set(logmsg, message, tmpmsg); + + level = VERBOSE_MAGIC2LEVEL(logmsg->message); + + tmpmsg = logger_strip_verbose_magic(logmsg->message, level); + if (tmpmsg) { + ast_string_field_set(logmsg, message, tmpmsg); + ast_free(tmpmsg); + } } AST_RWLIST_RDLOCK(&logchannels); @@ -1746,9 +1772,8 @@ void ast_log_backtrace(void) void __ast_verbose_ap(const char *file, int line, const char *func, int level, struct ast_callid *callid, const char *fmt, va_list ap) { const char *p; - struct ast_str *prefixed, *buf = NULL; + struct ast_str *prefixed, *buf; int res = 0; - const char *prefix = level >= 4 ? VERBOSE_PREFIX_4 : level == 3 ? VERBOSE_PREFIX_3 : level == 2 ? VERBOSE_PREFIX_2 : level == 1 ? VERBOSE_PREFIX_1 : ""; signed char magic = level > 9 ? -10 : -level - 1; /* 0 => -1, 1 => -2, etc. Can't pass NUL, as it is EOS-delimiter */ /* For compatibility with modules still calling ast_verbose() directly instead of using ast_verb() */ @@ -1767,18 +1792,18 @@ void __ast_verbose_ap(const char *file, int line, const char *func, int level, s } if (!(prefixed = ast_str_thread_get(&verbose_buf, VERBOSE_BUF_INIT_SIZE)) || - !(buf = ast_str_create(VERBOSE_BUF_INIT_SIZE))) { + !(buf = ast_str_thread_get(&verbose_build_buf, VERBOSE_BUF_INIT_SIZE))) { return; } res = ast_str_set_va(&buf, 0, fmt, ap); /* If the build failed then we can drop this allocated message */ if (res == AST_DYNSTR_BUILD_FAILED) { - ast_free(buf); return; } ast_str_reset(prefixed); + /* for every newline found in the buffer add verbose prefix data */ fmt = ast_str_buffer(buf); do { @@ -1787,22 +1812,12 @@ void __ast_verbose_ap(const char *file, int line, const char *func, int level, s } ++p; - if (ast_opt_timestamp) { - struct ast_tm tm; - char date[40]; - struct timeval now = ast_tvnow(); - ast_localtime(&now, &tm, NULL); - ast_strftime(date, sizeof(date), dateformat, &tm); - ast_str_append(&prefixed, 0, "%c[%s] %s", (char) magic, date, prefix); - } else { - ast_str_append(&prefixed, 0, "%c%s", (char) magic, prefix); - } + ast_str_append(&prefixed, 0, "%c", (char)magic); ast_str_append_substr(&prefixed, 0, fmt, p - fmt); fmt = p; } while (p && *p); ast_log_callid(__LOG_VERBOSE, file, line, func, callid, "%s", ast_str_buffer(prefixed)); - ast_free(buf); } void __ast_verbose(const char *file, int line, const char *func, int level, const char *fmt, ...) @@ -2121,3 +2136,9 @@ void ast_logger_unregister_level(const char *name) AST_RWLIST_UNLOCK(&logchannels); } } + +const char *ast_logger_get_dateformat(void) +{ + return dateformat; +} + diff --git a/main/optional_api.c b/main/optional_api.c index f9d5fc68ff..92f36eaf99 100644 --- a/main/optional_api.c +++ b/main/optional_api.c @@ -135,7 +135,6 @@ static struct optional_api *optional_api_create(const char *symname) struct optional_api *api; size_t size; - ast_verb(6, "%s: building api object\n", symname); size = sizeof(*api) + strlen(symname) + 1; api = ast_std_calloc(1, size); if (!api) { @@ -219,11 +218,8 @@ static void optional_api_user_relink(struct optional_api_user *user, struct optional_api *api) { if (api->impl && *user->optional_ref != api->impl) { - ast_verb(4, "%s: linking for %s\n", api->symname, user->module); *user->optional_ref = api->impl; } else if (!api->impl && *user->optional_ref != user->stub) { - ast_verb(4, "%s: stubbing for %s\n", api->symname, - user->module); *user->optional_ref = user->stub; } } @@ -252,8 +248,6 @@ void ast_optional_api_provide(const char *symname, ast_optional_fn impl) { struct optional_api *api; - ast_verb(4, "%s: providing\n", symname); - api = get_api(symname); if (!api) { ast_log(LOG_ERROR, "%s: Allocation failed\n", symname); @@ -268,8 +262,6 @@ void ast_optional_api_unprovide(const char *symname, ast_optional_fn impl) { struct optional_api *api; - ast_verb(4, "%s: un-providing\n", symname); - api = get_api(symname); if (!api) { ast_log(LOG_ERROR, "%s: Could not find api\n", symname); @@ -341,8 +333,6 @@ void ast_optional_api_unuse(const char *symname, ast_optional_fn *optional_ref, if (user->optional_ref == optional_ref) { if (*user->optional_ref != user->stub) { - ast_verb(4, "%s: stubbing for %s\n", symname, - module); *user->optional_ref = user->stub; } diff --git a/main/pbx.c b/main/pbx.c index faddc47747..0d0c7aafad 100644 --- a/main/pbx.c +++ b/main/pbx.c @@ -8613,7 +8613,6 @@ struct ast_context *ast_context_find_or_create(struct ast_context **extcontexts, *local_contexts = tmp; ast_hashtab_insert_safe(contexts_table, tmp); /*put this context into the tree */ ast_unlock_contexts(); - ast_debug(1, "Registered context '%s'(%p) in table %p registrar: %s\n", tmp->name, tmp, contexts_table, registrar); ast_verb(3, "Registered extension context '%s'; registrar: %s\n", tmp->name, registrar); } else { tmp->next = *local_contexts; @@ -8621,7 +8620,6 @@ struct ast_context *ast_context_find_or_create(struct ast_context **extcontexts, ast_hashtab_insert_immediate(exttable, tmp); /*put this context into the tree */ *local_contexts = tmp; - ast_debug(1, "Registered context '%s'(%p) in local table %p; registrar: %s\n", tmp->name, tmp, exttable, registrar); ast_verb(3, "Registered extension context '%s'; registrar: %s\n", tmp->name, registrar); } return tmp; @@ -11927,7 +11925,7 @@ int load_pbx(void) /* Initialize the PBX */ ast_verb(1, "Asterisk PBX Core Initializing\n"); - ast_verb(1, "Registering builtin applications:\n"); + ast_verb(2, "Registering builtin applications and functions:\n"); ast_cli_register_multiple(pbx_cli, ARRAY_LEN(pbx_cli)); ast_data_register_multiple_core(pbx_data_providers, ARRAY_LEN(pbx_data_providers)); __ast_custom_function_register(&exception_function, NULL); @@ -11935,7 +11933,6 @@ int load_pbx(void) /* Register builtin applications */ for (x = 0; x < ARRAY_LEN(builtins); x++) { - ast_verb(1, "[%s]\n", builtins[x].name); if (ast_register_application2(builtins[x].name, builtins[x].execute, NULL, NULL, NULL)) { ast_log(LOG_ERROR, "Unable to register builtin application '%s'\n", builtins[x].name); return -1; diff --git a/main/xmldoc.c b/main/xmldoc.c index 431eb1dd72..28bea86bd2 100644 --- a/main/xmldoc.c +++ b/main/xmldoc.c @@ -432,7 +432,7 @@ char *ast_xmldoc_printable(const char *bwinput, int withcolors) } if (withcolors) { - ast_str_append(&colorized, 0, "%s", term_end()); + ast_str_append(&colorized, 0, "%s", ast_term_reset()); if (!colorized) { return NULL; } diff --git a/res/parking/parking_applications.c b/res/parking/parking_applications.c index 5500e33164..51d6aff8f2 100644 --- a/res/parking/parking_applications.c +++ b/res/parking/parking_applications.c @@ -356,7 +356,7 @@ static int setup_park_common_datastore(struct ast_channel *parkee, const char *p if (!ast_strlen_zero(parker_dial_string)) { ast_channel_name_to_dial_string(parker_dial_string); - ast_verb(5, "Setting dial string to %s from %s value", parker_dial_string, attended_transfer ? "ATTENDEDTRANSFER" : "BLINDTRANSFER"); + ast_verb(4, "Setting Parker dial string to %s from %s value", parker_dial_string, attended_transfer ? "ATTENDEDTRANSFER" : "BLINDTRANSFER"); park_datastore->parker_dial_string = ast_strdup(parker_dial_string); } diff --git a/res/res_config_curl.c b/res/res_config_curl.c index 9dfcb0d9dd..660916a349 100644 --- a/res/res_config_curl.c +++ b/res/res_config_curl.c @@ -630,7 +630,7 @@ static int reload_module(void) static int unload_module(void) { ast_config_engine_deregister(&curl_engine); - ast_verb(1, "res_config_curl unloaded.\n"); + return 0; } @@ -653,7 +653,7 @@ static int load_module(void) reload_module(); ast_config_engine_register(&curl_engine); - ast_verb(1, "res_config_curl loaded.\n"); + return 0; } diff --git a/res/res_config_odbc.c b/res/res_config_odbc.c index 4806bd208a..dc46a983ef 100644 --- a/res/res_config_odbc.c +++ b/res/res_config_odbc.c @@ -1205,14 +1205,13 @@ static int unload_module (void) { ast_config_engine_deregister(&odbc_engine); - ast_verb(1, "res_config_odbc unloaded.\n"); return 0; } static int load_module (void) { ast_config_engine_register(&odbc_engine); - ast_verb(1, "res_config_odbc loaded.\n"); + return 0; } diff --git a/res/res_config_pgsql.c b/res/res_config_pgsql.c index 58925a0762..b8ab994a70 100644 --- a/res/res_config_pgsql.c +++ b/res/res_config_pgsql.c @@ -1334,7 +1334,7 @@ static int load_module(void) return AST_MODULE_LOAD_DECLINE; ast_config_engine_register(&pgsql_engine); - ast_verb(1, "PostgreSQL RealTime driver loaded.\n"); + ast_cli_register_multiple(cli_realtime, ARRAY_LEN(cli_realtime)); return 0; @@ -1352,7 +1352,6 @@ static int unload_module(void) } ast_cli_unregister_multiple(cli_realtime, ARRAY_LEN(cli_realtime)); ast_config_engine_deregister(&pgsql_engine); - ast_verb(1, "PostgreSQL RealTime unloaded.\n"); /* Destroy cached table info */ AST_LIST_LOCK(&psql_tables); diff --git a/res/res_fax.c b/res/res_fax.c index 54fc9f1efa..aaf1d2aff8 100644 --- a/res/res_fax.c +++ b/res/res_fax.c @@ -407,7 +407,7 @@ static void debug_check_frame_for_silence(struct ast_fax_session *s, unsigned in history->consec_ms = 0; if ((last_consec_frames != 0)) { - ast_verb(6, "Channel '%s' fax session '%u', [ %.3ld.%.6ld ], %s sent %u frames (%u ms) of %s.\n", + ast_verb(0, "Channel '%s' fax session '%u', [ %.3ld.%.6ld ], %s sent %u frames (%u ms) of %s.\n", s->channame, s->id, (long) diff.tv_sec, (long int) diff.tv_usec, (c2s) ? "channel" : "stack", last_consec_frames, last_consec_ms, (wassil) ? "silence" : "energy"); diff --git a/res/res_jabber.c b/res/res_jabber.c index dbc6135f33..d5079a6b56 100644 --- a/res/res_jabber.c +++ b/res/res_jabber.c @@ -2627,7 +2627,7 @@ static void aji_handle_subscribe(struct aji_client *client, ikspak *pak) ASTOBJ_UNREF(buddy, ast_aji_buddy_destroy); } default: - ast_verb(5, "JABBER: This is a subcription of type %i\n", pak->subtype); + ast_debug(3, "JABBER: This is a subcription of type %i\n", pak->subtype); } } diff --git a/res/res_odbc.c b/res/res_odbc.c index 7b967d0373..9cdcac35d5 100644 --- a/res/res_odbc.c +++ b/res/res_odbc.c @@ -546,7 +546,7 @@ struct odbc_cache_tables *ast_odbc_find_table(const char *database, const char * entry->octetlen = entry->size; } - ast_verb(10, "Found %s column with type %hd with len %ld, octetlen %ld, and numlen (%hd,%hd)\n", entry->name, entry->type, (long) entry->size, (long) entry->octetlen, entry->decimals, entry->radix); + ast_debug(3, "Found %s column with type %hd with len %ld, octetlen %ld, and numlen (%hd,%hd)\n", entry->name, entry->type, (long) entry->size, (long) entry->octetlen, entry->decimals, entry->radix); /* Insert column info into column list */ AST_LIST_INSERT_TAIL(&(tableptr->columns), entry, list); } -- GitLab