From ef4deb8ecd52a3c0b0952badc6ec0e5e48231011 Mon Sep 17 00:00:00 2001 From: George Joseph Date: Wed, 25 Jan 2017 05:50:43 -0700 Subject: [PATCH] debug_utilities: Add ast_logescalator The escalator works by creating a set of startup commands in cli.conf that set up logger channels and issue the debug commands for the subsystems specified. If asterisk is running when it is executed, the same commands will be issued to the running instance. The original cli.conf is saved before any changes are made and can be restored by executing '$prog --reset'. The log output will be stored in... $astlogdir/message.$uniqueid $astlogdir/debug.$uniqueid $astlogdir/dtmf.$uniqueid $astlogdir/fax.$uniqueid $astlogdir/security.$uniqueid $astlogdir/pjsip_history.$uniqueid $astlogdir/sip_history.$uniqueid Some minor tweaks were made to chan_sip, and res_pjsip_history so their history output could be send to a log channel as packets are captured. A minor tweak was also made to manager so events are output to verbose when "manager set debug on" is issued. Change-Id: I799f8e5013b86dc5282961b27383d134bf09e543 --- channels/chan_sip.c | 12 + contrib/scripts/ast_logescalator | 399 +++++++++++++++++++++++++++++++ main/manager.c | 6 +- res/res_pjsip_history.c | 91 ++++--- 4 files changed, 479 insertions(+), 29 deletions(-) create mode 100755 contrib/scripts/ast_logescalator diff --git a/channels/chan_sip.c b/channels/chan_sip.c index 288933fddd..3bb6e74b6d 100644 --- a/channels/chan_sip.c +++ b/channels/chan_sip.c @@ -613,6 +613,8 @@ ***/ +static int log_level = -1; + static int min_expiry = DEFAULT_MIN_EXPIRY; /*!< Minimum accepted registration time */ static int max_expiry = DEFAULT_MAX_EXPIRY; /*!< Maximum accepted registration time */ static int default_expiry = DEFAULT_DEFAULT_EXPIRY; @@ -3932,6 +3934,9 @@ static __attribute__((format(printf, 2, 0))) void append_history_va(struct sip_p } AST_LIST_INSERT_TAIL(p->history, hist, list); p->history_entries++; + if (log_level != -1) { + ast_log_dynamic_level(log_level, "%s\n", buf); + } } /*! \brief Append to SIP dialog history with arg list */ @@ -35172,6 +35177,10 @@ static int load_module(void) struct sip_peer *bogus_peer; ast_verbose("SIP channel loading...\n"); + log_level = ast_logger_register_level("SIP_HISTORY"); + if (log_level < 0) { + ast_log(LOG_WARNING, "Unable to register history log level\n"); + } if (STASIS_MESSAGE_TYPE_INIT(session_timeout_type)) { unload_module(); @@ -35572,6 +35581,9 @@ static int unload_module(void) sip_cfg.caps = NULL; STASIS_MESSAGE_TYPE_CLEANUP(session_timeout_type); + if (log_level != -1) { + ast_logger_unregister_level("SIP_HISTORY"); + } return 0; } diff --git a/contrib/scripts/ast_logescalator b/contrib/scripts/ast_logescalator new file mode 100755 index 0000000000..054ef9b9c0 --- /dev/null +++ b/contrib/scripts/ast_logescalator @@ -0,0 +1,399 @@ +#!/usr/bin/env bash +# Turn on extended globbing +shopt -s extglob +# Bail on any error +set -e + +prog=$(basename $0) + +print_help() { +cat < ] [ --sip-debug= ] + [ --iax2-debug= ] + + [ --agi-debug= ] [ --ami-debug= ] + [ --ari-debug= ] [ --cdr-debug= ] + [ --channel-debug= ] [ --rtp-debug= ] + [ --rtcp-debug= ] + + [ --dtmf-debug= ] [ --fax-debug= ] + [ --security-debug= ] + + [ --pjsip-history= ] [ --sip-history= ] + + [ --verbose= ] [ --debug= ] + ] ] + +DESCRIPTION + + Escalates log and/or debug levels on Asterisk subsystems. + + Options: + + --help + Print this help. + + --reset + Resets logging to the pre-escalation state. + + --uniqueid="" + Normally DATEFORMAT from ast_debug_tools.conf is used to make + the log files unique but you can set the unique id to + something else such as the Jira issue. Once any logging + is enabled, the uniqueid is stored in cli.conf so any future + on/off commands will use the same uniqueid. Use the --reset + option to reset it (and everything else). + + --pjsip-debug --sip-debug --iax2-debug --agi-debug --ami-debug + --ari-debug --cdr-debug --channel-debug --rtp-debug --rtcp-debug + Issues the subsystem appropriate command to turn on + or off debugging. These are usually functional debug messages + such as packet dumps as opposed to code level messages and usually + go to the VERBOSE log channel. + + --dtmf-debug --fax-debug --security-debug + These subsystems set up their own log channels so if turned + on, log files will be created in \$astlogdir for them. + + --pjsip-history --sip-history + The pjsip and sip channels have the ability to output an + abbreviated, one-line, packet summary. If enabled, the summaries + will be written to \$astlogdir/pjsip_history.\$UNIQUEID and + \$astlogdir/sip_history.\$UNIQUEID. + + --verbose-level --debug-level + Sets the levels for their respective messages. + +NOTES + + The escalator works by creating a set of startup commands in cli.conf + that set up logger channels and issue the debug commands. If asterisk + is running when $prog is executed, the same commands will be issued + to the running instance. The original cli.conf is saved before any + changes are made and can be restored by executing '$prog --reset'. + + The log output will be stored in... + \$astlogdir/message.\$uniqueid + \$astlogdir/debug.\$uniqueid + \$astlogdir/dtmf.\$uniqueid + \$astlogdir/fax.\$uniqueid + \$astlogdir/security.\$uniqueid + \$astlogdir/pjsip_history.\$uniqueid + \$astlogdir/sip_history.\$uniqueid + +EOF + exit 1 +} + +PJSIP_DEBUG_SPECIFIED=false +PJSIP_HISTORY_SPECIFIED=false +SIP_DEBUG_SPECIFIED=false +SIP_HISTORY_SPECIFIED=false +IAX2_DEBUG_SPECIFIED=false +ARI_DEBUG_SPECIFIED=false +AMI_DEBUG_SPECIFIED=false +AGI_DEBUG_SPECIFIED=false +CDR_DEBUG_SPECIFIED=false +CHANNEL_DEBUG_SPECIFIED=false +RTP_DEBUG_SPECIFIED=false +RTCP_DEBUG_SPECIFIED=false +DTMF_DEBUG_SPECIFIED=false +FAX_DEBUG_SPECIFIED=false +SECURITY_DEBUG_SPECIFIED=false +DEBUG_LEVEL_SPECIFIED=false +VERBOSE_LEVEL_SPECIFIED=false +DEBUGS=false +RESET=false + +declare -A DEBUG_COMMANDS=( +[PJSIP,on]="pjsip set logger on" [PJSIP,off]="pjsip set logger off" +[SIP,on]="sip set debug on" [SIP,off]="sip set debug off" +[IAX2,on]="iax2 set debug on" [IAX2,off]="iax2 set debug off" +[ARI,on]="ari set debug all on" [ARI,off]="ari set debug all off" +[AMI,on]="manager set debug on" [AMI,off]="manager set debug off" +[AGI,on]="agi set debug on" [AGI,off]="agi set debug off" +[CDR,on]="cdr set debug on" [CDR,off]="cdr set debug off" +[CHANNEL,on]="core set debug channel all" [CHANNEL,off]="core set debug channel all off" +[RTP,on]="rtp set debug on" [RTP,on]="rtp set debug off" +[RTCP,on]="rtcp set debug on" [RTCP,off]="rtcp set debug off" +) + +VERBOSE_LEVELS="NOTICE,WARNING,ERROR,VERBOSE" +DEBUG_LEVELS="DEBUG" + +# Read config files from least important to most important +[ -f /etc/asterisk/ast_debug_tools.conf ] && source /etc/asterisk/ast_debug_tools.conf +[ -f ~/ast_debug_tools.conf ] && source ~/ast_debug_tools.conf +[ -f ./ast_debug_tools.conf ] && source ./ast_debug_tools.conf + +DATEFORMAT=${DATEFORMAT:-'date +%FT%H-%M-%S%z'} +UNIQUEID=$($DATEFORMAT) +UNIQUEID_SPECIFIED=false + +for a in "$@" ; do + case "$a" in + --*-debug=*) + subsystem=${a%-debug=*} + subsystem=${subsystem#--} + flag=${a#*=} + if [[ ${flag,,} =~ ^y(es)?|on ]] ; then + eval ${subsystem^^}_DEBUG=true + else + eval ${subsystem^^}_DEBUG=false + fi + eval ${subsystem^^}_DEBUG_SPECIFIED=true + DEBUGS=true + ;; + --pjsip-history=*) + ;& + --sip-history=*) + subsystem=${a%-history=*} + subsystem=${subsystem#--} + if [[ ${a#*=} =~ ^[Yy].* ]] ; then + eval ${subsystem^^}_HISTORY=true + else + eval ${subsystem^^}_HISTORY=false + fi + eval ${subsystem^^}_HISTORY_SPECIFIED=true + DEBUGS=true + ;; + --verbose=*) + VERBOSE_LEVEL=${a#*=} + VERBOSE_LEVEL_SPECIFIED=true + DEBUGS=true + ;; + --debug=*) + DEBUG_LEVEL=${a#*=} + DEBUG_LEVEL_SPECIFIED=true + DEBUGS=true + ;; + --reset) + RESET=true + ;; + --uniqueid=*) + UNIQUEID=${a#*=} + UNIQUEID_SPECIFIED=true + DEBUGS=true + ;; + --help|*) + print_help + ;; + esac +done + +if $DEBUGS && $RESET ; then + echo "--reset must be specified by itself" + print_help +fi + +if ! $DEBUGS && ! $RESET ; then + echo "No options specified." + print_help +fi + +ASTERISK_IS_RUNNING=false +CONFIG_DIR=/etc/asterisk +LOG_DIR=/var/log/asterisk + +if [ "$(pidof asterisk)" != "" ] ; then + CONFIG_DIR=`asterisk -rx "core show settings" | sed -n -r -e "s/^\s*Configuration\s+directory:\s+(.*)$/\1/gp"` + LOG_DIR=`asterisk -rx "core show settings" | sed -n -r -e "s/^\s*Log\s+directory:\s+(.*)$/\1/gp"` + ASTERISK_IS_RUNNING=true +fi +CLI_CONF="$CONFIG_DIR/cli.conf" + +if [ ! -f "$CLI_CONF" ] ; then + echo "The location of cli.conf could not be determined." + exit 1 +fi + +if $RESET ; then + if [ -f "$CLI_CONF.unescalated" ] ; then + mv "$CLI_CONF.unescalated" "$CLI_CONF" + fi + if $ASTERISK_IS_RUNNING ; then + ( + asterisk -rx "core set verbose 0" + asterisk -rx "core set debug 0" + asterisk -rx "pjsip set logger off" + asterisk -rx "pjsip set history off" + asterisk -rx "sip set debug off" + asterisk -rx "sip set history off" + asterisk -rx "iax2 set debug off" + asterisk -rx "manager set debug off" + asterisk -rx "ari set debug all off" + asterisk -rx "agi set debug off" + asterisk -rx "rtp set debug off" + asterisk -rx "rtcp set debug off" + asterisk -rx "cdr set debug off" + asterisk -rx "core set debug channel all off" + asterisk -rx "logger reload" + ) >/dev/null 2>&1 || : + fi + exit 1 +fi + +if ! grep -q "; --START DEBUG_LOGGING-- ;" $CLI_CONF ; then + VERBOSE_LOG="$LOG_DIR/message.${UNIQUEID}" + DEBUG_LOG="$LOG_DIR/debug.${UNIQUEID}" + PJSIP_HISTORY_LOG="$LOG_DIR/pjsip_history.${UNIQUEID}" + SIP_HISTORY_LOG="$LOG_DIR/sip_history.${UNIQUEID}" + DTMF_LOG="$LOG_DIR/dtmf.${UNIQUEID}" + FAX_LOG="$LOG_DIR/fax.${UNIQUEID}" + SECURITY_LOG="$LOG_DIR/security.${UNIQUEID}" + + cp "$CLI_CONF" "$CLI_CONF.unescalated" + + sed -i -r -e "s/\[startup_commands\]/[startup_commands_original](!)/g" "$CLI_CONF" + + cat >> "$CLI_CONF" <<-EOF + ; --START DEBUG_LOGGING-- ; + + [pjsip_debug](!) + pjsip set logger on = yes + + [sip_debug](!) + sip set debug on = yes + + [iax2_debug](!) + iax2 set debug on = yes + + [ari_debug](!) + ari set debug all on = yes + + [ami_debug](!) + manager set debug on = yes + + [agi_debug](!) + agi set debug on = yes + + [cdr_debug](!) + cdr set debug on = yes + + [channel_debug](!) + core set debug channel all = yes + + [rtp_debug](!) + rtp set debug on = yes + + [rtcp_debug](!) + rtcp set debug on = yes + + [dtmf_debug](!) + logger add channel $DTMF_LOG DTMF = yes + + [fax_debug](!) + logger add channel $FAX_LOG FAX = yes + + [security_debug](!) + logger add channel $SECURITY_LOG SECURITY = yes + + [pjsip_history](!) + logger add channel $PJSIP_HISTORY_LOG PJSIP_HISTORY = yes + pjsip set history on = yes + + [sip_history](!) + logger add channel $SIP_HISTORY_LOG SIP_HISTORY = yes + sip set history on = yes + + [verbose_level](!) + core set verbose 3 = yes + + [debug_level](!) + core set debug 3 = yes + + [log_channels](!) + logger add channel $VERBOSE_LOG NOTICE,WARNING,ERROR,VERBOSE = yes + logger add channel $DEBUG_LOG DEBUG = yes + + [startup_commands](startup_commands_original,log_channels) + + ; --END DEBUG_LOGGING-- ; + EOF + +else + if $UNIQUEID_SPECIFIED ; then + echo "Debug logging is already active. Either rerun $prog without --uniqueid or with --reset to start over." + exit 1 + fi + + VERBOSE_LOG=$(sed -n -r -e "s@logger add channel ($LOG_DIR/message\..+)\s+NOTICE.*@\1@p" "$CLI_CONF") + DEBUG_LOG=$(sed -n -r -e "s@logger add channel ($LOG_DIR/debug\..+)\s+DEBUG.*@\1@p" "$CLI_CONF") + PJSIP_HISTORY_LOG=$(sed -n -r -e "s@logger add channel ($LOG_DIR/pjsip_history\..+)\s+PJSIP.*@\1@p" "$CLI_CONF") + SIP_HISTORY_LOG=$(sed -n -r -e "s@logger add channel ($LOG_DIR/sip_history\..+)\s+SIP.*@\1@p" "$CLI_CONF") + DTMF_LOG=$(sed -n -r -e "s@logger add channel ($LOG_DIR/dtmf\..+)\s+DTMF.*@\1@p" "$CLI_CONF") + FAX_LOG=$(sed -n -r -e "s@logger add channel ($LOG_DIR/fax\..+)\s+FAX.*@\1@p" "$CLI_CONF") + SECURITY_LOG=$(sed -n -r -e "s@logger add channel ($LOG_DIR/security\..+)\s+SECURITY.*@\1@p" "$CLI_CONF") +fi + +for x in PJSIP SIP ARI AMI AGI ARI IAX2 CDR RTP RTCP ; do + if eval \$${x}_DEBUG_SPECIFIED ; then + if eval \$${x}_DEBUG ; then + if $ASTERISK_IS_RUNNING ; then + asterisk -rx "${DEBUG_COMMANDS[$x,on]}" + fi + egrep -q "^\[startup_commands\].*${x,,}_debug.*" "$CLI_CONF" || + sed -i -r -e "/\[startup_commands\]/ s/\((.*)\)/(\1,${x,,}_debug)/g" "$CLI_CONF" + else + if $ASTERISK_IS_RUNNING ; then + asterisk -rx "${DEBUG_COMMANDS[$x,off]}" + fi + sed -i -r -e "/\[startup_commands\].*${x,,}_debug.*/ s/,${x,,}_debug//g" "$CLI_CONF" + fi + fi +done + +for x in DTMF FAX SECURITY ; do + if eval \$${x}_DEBUG_SPECIFIED ; then + if eval \$${x}_DEBUG ; then + if $ASTERISK_IS_RUNNING ; then + asterisk -rx "$(eval "echo logger add channel \$${x}_LOG ${x}")" >/dev/null 2>&1 + fi + egrep -q "^\[startup_commands\].*${x,,}_debug.*" "$CLI_CONF" || + sed -i -r -e "/\[startup_commands\]/ s/\((.*)\)/(\1,${x,,}_debug)/g" "$CLI_CONF" + else + if $ASTERISK_IS_RUNNING ; then + asterisk -rx "$(eval "echo logger remove channel \$${x}_LOG")" + fi + sed -i -r -e "/\[startup_commands\].*${x,,}_debug.*/ s/,${x,,}_debug//g" "$CLI_CONF" + fi + fi +done + +for x in PJSIP SIP ; do + if eval \$${x}_HISTORY_SPECIFIED ; then + if eval \$${x}_HISTORY ; then + if $ASTERISK_IS_RUNNING ; then + asterisk -rx "$(eval "echo logger add channel \$${x}_HISTORY_LOG ${x}_HISTORY")" + asterisk -rx "${x,,} set history on" + fi + egrep -q "^\[startup_commands\].*${x,,}_history.*" "$CLI_CONF" || + sed -i -r -e "/\[startup_commands\]/ s/\((.*)\)/(\1,${x,,}_history)/g" "$CLI_CONF" + else + if $ASTERISK_IS_RUNNING ; then + asterisk -rx "$(eval "echo logger remove channel \$${x}_HISTORY_LOG")" + asterisk -rx "${x,,} set history off" + fi + sed -i -r -e "/\[startup_commands\].*${x,,}_history.*/ s/,${x,,}_history//g" "$CLI_CONF" + fi + fi +done + +for x in VERBOSE DEBUG ; do + if eval \$${x}_LEVEL_SPECIFIED ; then + if $ASTERISK_IS_RUNNING ; then + asterisk -rx "$(eval "echo logger add channel \$${x}_LOG \$${x}_LEVELS")" + asterisk -rx "$(eval "echo core set ${x,,} \$${x}_LEVEL")" + fi + sed -i -r -e "$(eval "echo s/core set ${x,,} .*/core set ${x,,} \$${x}_LEVEL/g")" "$CLI_CONF" + egrep -q "^\[startup_commands\].*${x,,}_level.*" "$CLI_CONF" || + sed -i -r -e "/\[startup_commands\]/ s/\((.*)\)/(\1,${x,,}_level)/g" "$CLI_CONF" + fi +done diff --git a/main/manager.c b/main/manager.c index f059015c7d..dfe056438d 100644 --- a/main/manager.c +++ b/main/manager.c @@ -5889,7 +5889,11 @@ static int match_filter(struct mansession *s, char *eventdata) { int result = 0; - ast_debug(3, "Examining AMI event:\n%s\n", eventdata); + if (manager_debug) { + ast_verbose("<-- Examining AMI event: -->\n%s\n", eventdata); + } else { + ast_debug(3, "Examining AMI event:\n%s\n", eventdata); + } if (!ao2_container_count(s->session->whitefilters) && !ao2_container_count(s->session->blackfilters)) { return 1; /* no filtering means match all */ } else if (ao2_container_count(s->session->whitefilters) && !ao2_container_count(s->session->blackfilters)) { diff --git a/res/res_pjsip_history.c b/res/res_pjsip_history.c index 41c5bdf696..853ba319ea 100644 --- a/res/res_pjsip_history.c +++ b/res/res_pjsip_history.c @@ -157,6 +157,9 @@ struct expression_token { char field[]; }; +/*! \brief Log level for history output */ +static int log_level = -1; + /*! * \brief Operator callback for determining equality */ @@ -644,6 +647,41 @@ static struct pjsip_history_entry *pjsip_history_entry_alloc(pjsip_msg *msg) return entry; } +/*! \brief Format single line history entry */ +static void sprint_list_entry(struct pjsip_history_entry *entry, char *line, int len) +{ + char addr[64]; + + if (entry->transmitted) { + pj_sockaddr_print(&entry->dst, addr, sizeof(addr), 3); + } else { + pj_sockaddr_print(&entry->src, addr, sizeof(addr), 3); + } + + if (entry->msg->type == PJSIP_REQUEST_MSG) { + char uri[128]; + + pjsip_uri_print(PJSIP_URI_IN_REQ_URI, entry->msg->line.req.uri, uri, sizeof(uri)); + snprintf(line, len, "%-5.5d %-10.10ld %-5.5s %-24.24s %.*s %s SIP/2.0", + entry->number, + entry->timestamp.tv_sec, + entry->transmitted ? "* ==>" : "* <==", + addr, + (int)pj_strlen(&entry->msg->line.req.method.name), + pj_strbuf(&entry->msg->line.req.method.name), + uri); + } else { + snprintf(line, len, "%-5.5d %-10.10ld %-5.5s %-24.24s SIP/2.0 %u %.*s", + entry->number, + entry->timestamp.tv_sec, + entry->transmitted ? "* ==>" : "* <==", + addr, + entry->msg->line.status.code, + (int)pj_strlen(&entry->msg->line.status.reason), + pj_strbuf(&entry->msg->line.status.reason)); + } +} + /*! \brief PJSIP callback when a SIP message is transmitted */ static pj_status_t history_on_tx_msg(pjsip_tx_data *tdata) { @@ -665,6 +703,13 @@ static pj_status_t history_on_tx_msg(pjsip_tx_data *tdata) AST_VECTOR_APPEND(&vector_history, entry); ast_mutex_unlock(&history_lock); + if (log_level != -1) { + char line[256]; + + sprint_list_entry(entry, line, sizeof(line)); + ast_log_dynamic_level(log_level, "%s\n", line); + } + return PJ_SUCCESS; } @@ -698,6 +743,13 @@ static pj_bool_t history_on_rx_msg(pjsip_rx_data *rdata) AST_VECTOR_APPEND(&vector_history, entry); ast_mutex_unlock(&history_lock); + if (log_level != -1) { + char line[256]; + + sprint_list_entry(entry, line, sizeof(line)); + ast_log_dynamic_level(log_level, "%s\n", line); + } + return PJ_FALSE; } @@ -1118,38 +1170,12 @@ static void display_entry_list(struct ast_cli_args *a, struct vector_history_t * for (i = 0; i < AST_VECTOR_SIZE(vec); i++) { struct pjsip_history_entry *entry; - char addr[64]; char line[256]; entry = AST_VECTOR_GET(vec, i); + sprint_list_entry(entry, line, sizeof(line)); - if (entry->transmitted) { - pj_sockaddr_print(&entry->dst, addr, sizeof(addr), 3); - } else { - pj_sockaddr_print(&entry->src, addr, sizeof(addr), 3); - } - - if (entry->msg->type == PJSIP_REQUEST_MSG) { - char uri[128]; - - pjsip_uri_print(PJSIP_URI_IN_REQ_URI, entry->msg->line.req.uri, uri, sizeof(uri)); - snprintf(line, sizeof(line), "%.*s %s SIP/2.0", - (int)pj_strlen(&entry->msg->line.req.method.name), - pj_strbuf(&entry->msg->line.req.method.name), - uri); - } else { - snprintf(line, sizeof(line), "SIP/2.0 %u %.*s", - entry->msg->line.status.code, - (int)pj_strlen(&entry->msg->line.status.reason), - pj_strbuf(&entry->msg->line.status.reason)); - } - - ast_cli(a->fd, "%-5.5d %-10.10ld %-5.5s %-24.24s %s\n", - entry->number, - entry->timestamp.tv_sec, - entry->transmitted ? "* ==>" : "* <==", - addr, - line); + ast_cli(a->fd, "%s\n", line); } } @@ -1319,6 +1345,11 @@ static int load_module(void) { CHECK_PJSIP_MODULE_LOADED(); + log_level = ast_logger_register_level("PJSIP_HISTORY"); + if (log_level < 0) { + ast_log(LOG_WARNING, "Unable to register history log level\n"); + } + pj_caching_pool_init(&cachingpool, &pj_pool_factory_default_policy, 0); AST_VECTOR_INIT(&vector_history, HISTORY_INITIAL_SIZE); @@ -1339,6 +1370,10 @@ static int unload_module(void) pj_caching_pool_destroy(&cachingpool); + if (log_level != -1) { + ast_logger_unregister_level("PJSIP_HISTORY"); + } + return 0; }