[POST-1.0.2][RFC][PATCH 0/2] Fine-grained logging: per-session logging
Hi, the following series of patches adds a per-session logging capability (patch 1) and converts a part of mod_sofia over to use the new functions as an example (patch 2). Note: This is one of two possible ways to implement the feature... (see below) Why?: Some of "us" are running fs with high call volumes and turning on debugging globally causes massive amounts of space used and reduced performance. This patch extends the logging api to be able to change the log level for e.g. a single session (either from the dialplan or via API command / C API) for diagnosing problems. How?: The core patch adds a couple of new functions: switch_core_session_log_printf(switch_core_session_t *, ...) switch_core_session_set_loglevel() switch_core_session_get_loglevel() A new API command "uuid_loglevel <uuid> <level>" (mod_commands.c) and a dialplan app "session_loglevel" (mod_dptools.c part of the core patch) are included. The default loglevel of a session is the current global log level. All instances of switch_log_printf() that log session-specific messages need to be converted to the new log function for this to be useful! (The second patch has the changes for mod_sofia.c) Alternative implementation: There's a second way to implement this feature, without adding another log_printf function: switch_log_printf has a "userdata" parameter that is currently unused, which could be used to pass an additional value (e.g. a session) by adding additional SWITCH_*_LOG helper macros. A session log call could look like this: switch_log_printf(SWITCH_SESSION_LOG(session), SWITCH_LOG_DEBUG, "I'm a session debug message\n"); Pro: - Can be extended for other type of log actions (e.g. if we want to implement even more fine-grained logging, per-module etc.) without adding more switch_*_log_printf functions Con: - More work for switch_log_printf() Now it's up to you to discuss which way we want to go and if this feature is deemed useful :P Stefan P.S.: The patches are available via http too: http://oss.axsentis.de/people/stkn/freeswitch/fs-r10758-session_loglevel.pat... http://oss.axsentis.de/people/stkn/freeswitch/fs-r10758-session_loglevel-con... Diffstat of the core patch: include/private/switch_core_pvt.h | 1 include/switch_core.h | 15 ++++++++++ include/switch_log.h | 18 +++++++++++++ mod/applications/mod_commands/mod_commands.c | 37 +++++++++++++++++++++++++++ mod/applications/mod_dptools/mod_dptools.c | 19 +++++++++++++ switch_core_session.c | 15 ++++++++++ switch_log.c | 34 ++++++++++++++++++++---- 7 files changed, 133 insertions(+), 6 deletions(-) -- Stefan Knoblich Systemadministrator axsentis GmbH Eupener Strasse 74 50933 Köln Tel: 0180 - 506 705 521* Fax: 0180 - 506 705 529* E-Mail: s.knoblich@axsentis.de Web: www.axsentis.de Eingetragen beim AG Köln: HR B 56238 UST-ID: DE244977565 Gesellschafter-Geschäftsführer: Yan Lecomte, Eduard Schlein, Apostolos Varsamis *14ct/min aus dem Festnetz der T-Com | dtms
diff --git a/src/include/private/switch_core_pvt.h b/src/include/private/switch_core_pvt.h index 040a6ec..c3b9fc2 100644 --- a/src/include/private/switch_core_pvt.h +++ b/src/include/private/switch_core_pvt.h @@ -98,6 +98,7 @@ struct switch_core_session { switch_size_t id; switch_session_flag_t flags; int thread_running; + switch_log_level_t log_level; switch_channel_t *channel; switch_io_event_hooks_t event_hooks; diff --git a/src/include/switch_core.h b/src/include/switch_core.h index 7670435..89ffbf3 100644 --- a/src/include/switch_core.h +++ b/src/include/switch_core.h @@ -729,6 +729,21 @@ SWITCH_DECLARE(void *) switch_core_session_get_private(_In_ switch_core_session_ SWITCH_DECLARE(switch_status_t) switch_core_session_set_private(_In_ switch_core_session_t *session, _In_ void *private_info); /*! + \brief Set session loglevel + \param session the session + \param loglevel the desired loglevel + \return SWITCH_STATUS_SUCCESS on success +*/ +SWITCH_DECLARE(switch_status_t) switch_core_session_set_loglevel(_In_ switch_core_session_t *session, _In_ switch_log_level_t loglevel); + +/*! + \brief Get session loglevel + \param session the session + \return the loglevel +*/ +SWITCH_DECLARE(switch_log_level_t) switch_core_session_get_loglevel(_In_ switch_core_session_t *session); + +/*! \brief Add a logical stream to a session \param session the session to add the stream to \param private_info an optional pointer to private data for the new stream diff --git a/src/include/switch_log.h b/src/include/switch_log.h index 01efc16..c7ec263 100644 --- a/src/include/switch_log.h +++ b/src/include/switch_log.h @@ -99,6 +99,24 @@ SWITCH_DECLARE(void) switch_log_printf(_In_ switch_text_channel_t channel, _In_z _In_z_ const char *func, _In_ int line, _In_opt_z_ const char *userdata, _In_ switch_log_level_t level, _In_z_ _Printf_format_string_ const char *fmt, ...) PRINTF_FUNCTION(7, 8); + +/*! + \brief Write session log data to the logging engine + \param session the session to log for + \param channel the log channel to write to + \param file the current file + \param func the current function + \param line the current line + \param userdata ununsed + \param level the current log level + \param fmt desired format + \param ... variable args + \note there are channel macros to supply the 4 parameters after session +*/ +SWITCH_DECLARE(void) switch_core_session_log_printf(_In_ switch_core_session_t *session, _In_ switch_text_channel_t channel, _In_z_ const char *file, + _In_z_ const char *func, _In_ int line, + _In_opt_z_ const char *userdata, _In_ switch_log_level_t level, + _In_z_ _Printf_format_string_ const char *fmt, ...) PRINTF_FUNCTION(8, 9); #endif /*! \brief Shut down the logging engine diff --git a/src/mod/applications/mod_commands/mod_commands.c b/src/mod/applications/mod_commands/mod_commands.c index 677c5fa..52fd2e2 100644 --- a/src/mod/applications/mod_commands/mod_commands.c +++ b/src/mod/applications/mod_commands/mod_commands.c @@ -1296,6 +1296,41 @@ SWITCH_STANDARD_API(uuid_deflect) return SWITCH_STATUS_SUCCESS; } +#define UUID_LOGLEVEL_SYNTAX "<uuid> <level>" +SWITCH_STANDARD_API(uuid_loglevel) +{ + switch_core_session_t *tsession = NULL; + char *uuid = NULL, *text = NULL; + + if (!switch_strlen_zero(cmd) && (uuid = strdup(cmd))) { + if ((text = strchr(uuid, ' '))) { + *text++ = '\0'; + } + } + + if (switch_strlen_zero(uuid) || switch_strlen_zero(text)) { + stream->write_function(stream, "-USAGE: %s\n", UUID_LOGLEVEL_SYNTAX); + } else { + switch_log_level_t level = switch_log_str2level(text); + + if (level == SWITCH_LOG_INVALID) { + stream->write_function(stream, "-ERR Invalid log level!\n"); + } + else if ((tsession = switch_core_session_locate(uuid))) { + + switch_core_session_set_loglevel(tsession, level); + stream->write_function(stream, "+OK\n"); + switch_core_session_rwunlock(tsession); + } + else { + stream->write_function(stream, "-ERR No Such Channel %s!\n", uuid); + } + } + + switch_safe_free(uuid); + return SWITCH_STATUS_SUCCESS; +} + #define SCHED_TRANSFER_SYNTAX "[+]<time> <uuid> <extension> [<dialplan>] [<context>]" SWITCH_STANDARD_API(sched_transfer_function) { @@ -3148,6 +3183,8 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_commands_load) SWITCH_ADD_API(commands_api_interface, "system", "Execute a system command", system_function, SYSTEM_SYNTAX); SWITCH_ADD_API(commands_api_interface, "time_test", "time_test", time_test_function, "<mss>"); + SWITCH_ADD_API(commands_api_interface, "uuid_loglevel", "set loglevel on session", uuid_loglevel, UUID_LOGLEVEL_SYNTAX); + /* indicate that the module should continue to be loaded */ return SWITCH_STATUS_NOUNLOAD; } diff --git a/src/mod/applications/mod_dptools/mod_dptools.c b/src/mod/applications/mod_dptools/mod_dptools.c index 52fc3e9..70d3ebd 100644 --- a/src/mod/applications/mod_dptools/mod_dptools.c +++ b/src/mod/applications/mod_dptools/mod_dptools.c @@ -1648,6 +1648,23 @@ SWITCH_STANDARD_APP(phrase_function) } } +#define SESSION_LOGLEVEL_SYNTAX "<level>" +SWITCH_STANDARD_APP(session_loglevel_function) +{ + if (!switch_strlen_zero(data)) { + switch_log_level_t level = switch_log_str2level(data); + + if (level == SWITCH_LOG_INVALID) { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid log level: %s\n", data); + } else { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Setting log level \"%s\" on session\n", switch_log_level2str(level)); + switch_core_session_set_loglevel(session, level); + } + } else { + switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "No log level specified\n"); + } +} + SWITCH_STANDARD_APP(playback_function) { @@ -2428,6 +2445,8 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_dptools_load) SWITCH_ADD_APP(app_interface, "wait_for_silence", "wait_for_silence", "wait_for_silence", wait_for_silence_function, WAIT_FOR_SILENCE_SYNTAX, SAF_NONE); + SWITCH_ADD_APP(app_interface, "session_loglevel", "session_loglevel", "session_loglevel", session_loglevel_function, SESSION_LOGLEVEL_SYNTAX, SAF_NONE); + SWITCH_ADD_DIALPLAN(dp_interface, "inline", inline_dialplan_hunt); /* indicate that the module should continue to be loaded */ diff --git a/src/switch_core_session.c b/src/switch_core_session.c index 58f3853..63e80cf 100644 --- a/src/switch_core_session.c +++ b/src/switch_core_session.c @@ -221,6 +221,19 @@ SWITCH_DECLARE(int) switch_core_session_get_stream_count(switch_core_session_t * return session->stream_count; } +SWITCH_DECLARE(switch_status_t) switch_core_session_set_loglevel(switch_core_session_t *session, switch_log_level_t log_level) +{ + switch_assert(session != NULL); + session->log_level = log_level; + return SWITCH_STATUS_SUCCESS; +} + +SWITCH_DECLARE(switch_log_level_t) switch_core_session_get_loglevel(switch_core_session_t *session) +{ + switch_assert(session != NULL); + return session->log_level; +} + SWITCH_DECLARE(switch_call_cause_t) switch_core_session_resurrect_channel(const char *endpoint_name, switch_core_session_t **new_session, switch_memory_pool_t **pool, void *data) { @@ -1090,6 +1103,8 @@ SWITCH_DECLARE(switch_core_session_t *) switch_core_session_request_uuid(switch_ switch_uuid_format(session->uuid_str, &uuid); } + session->log_level = runtime.hard_log_level; + session->endpoint_interface = endpoint_interface; session->raw_write_frame.data = session->raw_write_buf; session->raw_write_frame.buflen = sizeof(session->raw_write_buf); diff --git a/src/switch_log.c b/src/switch_log.c index 4804f6d..31b860e 100644 --- a/src/switch_log.c +++ b/src/switch_log.c @@ -234,13 +234,12 @@ static void *SWITCH_THREAD_FUNC log_thread(switch_thread_t *thread, void *obj) } #define do_mods (LOG_QUEUE && THREAD_RUNNING) -SWITCH_DECLARE(void) switch_log_printf(switch_text_channel_t channel, const char *file, const char *func, int line, - const char *userdata, switch_log_level_t level, const char *fmt, ...) +static void __switch_log_printf(switch_text_channel_t channel, const char *file, const char *func, int line, + const char *userdata, switch_log_level_t level, const char *fmt, va_list ap) { char *data = NULL; char *new_fmt = NULL; int ret = 0; - va_list ap; FILE *handle; const char *filep = (file ? switch_cut_path(file) : ""); const char *funcp = (func ? func : ""); @@ -255,8 +254,6 @@ SWITCH_DECLARE(void) switch_log_printf(switch_text_channel_t channel, const char switch_assert(level < SWITCH_LOG_INVALID); - va_start(ap, fmt); - handle = switch_core_data_channel(channel); if (channel != SWITCH_CHANNEL_ID_LOG_CLEAN) { @@ -275,7 +272,6 @@ SWITCH_DECLARE(void) switch_log_printf(switch_text_channel_t channel, const char } ret = switch_vasprintf(&data, fmt, ap); - va_end(ap); if (ret == -1) { fprintf(stderr, "Memory Error\n"); @@ -381,6 +377,32 @@ SWITCH_DECLARE(void) switch_log_printf(switch_text_channel_t channel, const char } } +SWITCH_DECLARE(void) switch_log_printf(switch_text_channel_t channel, const char *file, const char *func, int line, + const char *userdata, switch_log_level_t level, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + __switch_log_printf(channel, file, func, line, userdata, level, fmt, ap); + va_end(ap); +} + +SWITCH_DECLARE(void) switch_core_session_log_printf(switch_core_session_t *session, switch_text_channel_t channel, const char *file, const char *func, int line, + const char *userdata, switch_log_level_t level, const char *fmt, ...) +{ + va_list ap; + + switch_assert(session != NULL); + + if (level > session->log_level) { + return; + } + + va_start(ap, fmt); + __switch_log_printf(channel, file, func, line, userdata, level, fmt, ap); + va_end(ap); +} + SWITCH_DECLARE(switch_status_t) switch_log_init(switch_memory_pool_t *pool, switch_bool_t colorize) { switch_thread_t *thread;
diff --git a/src/mod/endpoints/mod_sofia/mod_sofia.c b/src/mod/endpoints/mod_sofia/mod_sofia.c index 86f4d55..a3f1fc2 100644 --- a/src/mod/endpoints/mod_sofia/mod_sofia.c +++ b/src/mod/endpoints/mod_sofia/mod_sofia.c @@ -80,7 +80,7 @@ static switch_status_t sofia_on_init(switch_core_session_t *session) tech_pvt->read_frame.buflen = SWITCH_RTP_MAX_BUF_LEN; switch_mutex_lock(tech_pvt->sofia_mutex); - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA INIT\n", switch_channel_get_name(channel)); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA INIT\n", switch_channel_get_name(channel)); if (switch_channel_test_flag(channel, CF_PROXY_MODE) || switch_channel_test_flag(channel, CF_PROXY_MEDIA)) { sofia_glue_tech_absorb_sdp(tech_pvt); } @@ -127,7 +127,7 @@ static switch_status_t sofia_on_routing(switch_core_session_t *session) switch_clear_flag_locked(tech_pvt, TFLAG_SIP_HOLD); } - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA ROUTING\n", switch_channel_get_name(switch_core_session_get_channel(session))); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA ROUTING\n", switch_channel_get_name(switch_core_session_get_channel(session))); return SWITCH_STATUS_SUCCESS; } @@ -142,7 +142,7 @@ static switch_status_t sofia_on_reset(switch_core_session_t *session) switch_clear_flag_locked(tech_pvt, TFLAG_SIP_HOLD); } - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA RESET\n", switch_channel_get_name(switch_core_session_get_channel(session))); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA RESET\n", switch_channel_get_name(switch_core_session_get_channel(session))); return SWITCH_STATUS_SUCCESS; } @@ -157,7 +157,7 @@ static switch_status_t sofia_on_hibernate(switch_core_session_t *session) switch_clear_flag_locked(tech_pvt, TFLAG_SIP_HOLD); } - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA HIBERNATE\n", switch_channel_get_name(switch_core_session_get_channel(session))); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA HIBERNATE\n", switch_channel_get_name(switch_core_session_get_channel(session))); return SWITCH_STATUS_SUCCESS; } @@ -170,7 +170,7 @@ static switch_status_t sofia_on_execute(switch_core_session_t *session) if (!switch_test_flag(tech_pvt, TFLAG_HOLD_LOCK)) { switch_clear_flag_locked(tech_pvt, TFLAG_SIP_HOLD); } - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA EXECUTE\n", switch_channel_get_name(switch_core_session_get_channel(session))); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s SOFIA EXECUTE\n", switch_channel_get_name(switch_core_session_get_channel(session))); return SWITCH_STATUS_SUCCESS; } @@ -250,7 +250,7 @@ switch_status_t sofia_on_hangup(switch_core_session_t *session) if (!switch_strlen_zero(ps_cause) && (!strncasecmp(ps_cause, "sip:", 4) || !strncasecmp(ps_cause, "sips:", 5))) { int new_cause = atoi(sofia_glue_strip_proto(ps_cause)); if (new_cause) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s Overriding SIP cause %d with %d from the other leg\n", + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s Overriding SIP cause %d with %d from the other leg\n", switch_channel_get_name(channel), sip_cause, new_cause); sip_cause = new_cause; } @@ -284,7 +284,7 @@ switch_status_t sofia_on_hangup(switch_core_session_t *session) sofia_glue_deactivate_rtp(tech_pvt); - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Channel %s hanging up, cause: %s\n", + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Channel %s hanging up, cause: %s\n", switch_channel_get_name(channel), switch_channel_cause2str(cause)); if (tech_pvt->hash_key) { @@ -341,14 +341,14 @@ switch_status_t sofia_on_hangup(switch_core_session_t *session) if (!tech_pvt->got_bye) { switch_channel_set_variable(channel, "sip_hangup_disposition", "send_bye"); } - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Sending BYE to %s\n", switch_channel_get_name(channel)); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Sending BYE to %s\n", switch_channel_get_name(channel)); nua_bye(tech_pvt->nh, SIPTAG_REASON_STR(reason), TAG_IF(!switch_strlen_zero(bye_headers), SIPTAG_HEADER_STR(bye_headers)), TAG_END()); } else { if (switch_test_flag(tech_pvt, TFLAG_OUTBOUND)) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Sending CANCEL to %s\n", switch_channel_get_name(channel)); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Sending CANCEL to %s\n", switch_channel_get_name(channel)); if (!tech_pvt->got_bye) { switch_channel_set_variable(channel, "sip_hangup_disposition", "send_cancel"); } @@ -358,7 +358,7 @@ switch_status_t sofia_on_hangup(switch_core_session_t *session) TAG_IF(!switch_strlen_zero(bye_headers), SIPTAG_HEADER_STR(bye_headers)), TAG_END()); } else { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Responding to INVITE with: %d\n", sip_cause); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Responding to INVITE with: %d\n", sip_cause); if (!tech_pvt->got_bye) { switch_channel_set_variable(channel, "sip_hangup_disposition", "send_refuse"); } @@ -400,13 +400,13 @@ switch_status_t sofia_on_hangup(switch_core_session_t *session) static switch_status_t sofia_on_exchange_media(switch_core_session_t *session) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "SOFIA LOOPBACK\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "SOFIA LOOPBACK\n"); return SWITCH_STATUS_SUCCESS; } static switch_status_t sofia_on_soft_execute(switch_core_session_t *session) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "SOFIA TRANSMIT\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "SOFIA TRANSMIT\n"); return SWITCH_STATUS_SUCCESS; } @@ -447,7 +447,7 @@ static switch_status_t sofia_answer_channel(switch_core_session_t *session) SOATAG_USER_SDP_STR(tech_pvt->local_sdp_str), SOATAG_REUSE_REJECTED(1), SOATAG_ORDERED_USER(1), SOATAG_AUDIO_AUX("cn telephone-event"), NUTAG_INCLUDE_EXTRA_SDP(1), TAG_END()); - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "3PCC-PROXY, Sent a 200 OK, waiting for ACK\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "3PCC-PROXY, Sent a 200 OK, waiting for ACK\n"); /* Unlock the session signal to allow the ack to make it in */ // Maybe we should timeout? @@ -460,14 +460,14 @@ static switch_status_t sofia_answer_channel(switch_core_session_t *session) /* Regain lock on sofia */ switch_mutex_lock(tech_pvt->sofia_mutex); - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "3PCC-PROXY, Done waiting for ACK\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "3PCC-PROXY, Done waiting for ACK\n"); } if ((is_proxy && !b_sdp) || switch_test_flag(tech_pvt, TFLAG_LATE_NEGOTIATION) || !tech_pvt->iananame) { switch_clear_flag_locked(tech_pvt, TFLAG_LATE_NEGOTIATION); if (is_proxy) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Disabling proxy mode due to call answer with no bridge\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Disabling proxy mode due to call answer with no bridge\n"); switch_channel_clear_flag(channel, CF_PROXY_MEDIA); switch_channel_clear_flag(channel, CF_PROXY_MODE); } @@ -499,7 +499,7 @@ static switch_status_t sofia_answer_channel(switch_core_session_t *session) if (tech_pvt->nh) { if (tech_pvt->local_sdp_str) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Local SDP %s:\n%s\n", switch_channel_get_name(channel), tech_pvt->local_sdp_str); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Local SDP %s:\n%s\n", switch_channel_get_name(channel), tech_pvt->local_sdp_str); } } } @@ -731,7 +731,7 @@ static switch_status_t sofia_read_frame(switch_core_session_t *session, switch_f int rtp_hold_timeout_sec = 0; tech_pvt->codec_ms = codec_ms; - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Changing codec ptime to %d. I bet you have a linksys/sipura =D\n", tech_pvt->codec_ms); switch_core_codec_destroy(&tech_pvt->read_codec); switch_core_codec_destroy(&tech_pvt->write_codec); @@ -937,7 +937,7 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi switch (msg->message_id) { case SWITCH_MESSAGE_INDICATE_TRANSCODING_NECESSARY: if (tech_pvt->rtp_session && switch_rtp_test_flag(tech_pvt->rtp_session, SWITCH_RTP_FLAG_PASS_RFC2833)) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Cannot pass 2833 on a transcoded call.\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Cannot pass 2833 on a transcoded call.\n"); switch_rtp_clear_flag(tech_pvt->rtp_session, SWITCH_RTP_FLAG_PASS_RFC2833); } goto end; @@ -1035,7 +1035,7 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi case SWITCH_MESSAGE_INDICATE_MEDIA_REDIRECT: { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Sending media re-direct:\n%s\n", msg->string_arg); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Sending media re-direct:\n%s\n", msg->string_arg); tech_pvt->local_sdp_str = switch_core_session_strdup(session, msg->string_arg); switch_set_flag_locked(tech_pvt, TFLAG_SENT_UPDATE); sofia_glue_do_invite(session); @@ -1111,11 +1111,11 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi case SWITCH_MESSAGE_INDICATE_REDIRECT: if (!switch_strlen_zero(msg->string_arg)) { if (!switch_channel_test_flag(channel, CF_ANSWERED)) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Redirecting to %s\n", msg->string_arg); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Redirecting to %s\n", msg->string_arg); nua_respond(tech_pvt->nh, SIP_302_MOVED_TEMPORARILY, SIPTAG_CONTACT_STR(msg->string_arg), TAG_END()); switch_set_flag_locked(tech_pvt, TFLAG_BYE); } else { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Too late for redirecting to %s, already answered\n", msg->string_arg); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Too late for redirecting to %s, already answered\n", msg->string_arg); } } break; @@ -1178,7 +1178,7 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi if (switch_strlen_zero(to_host)) { to_host = switch_channel_get_variable(channel, "sip_to_host"); } - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Challenging call %s\n", to_uri); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Challenging call %s\n", to_uri); sofia_reg_auth_challenge(NULL, tech_pvt->profile, tech_pvt->nh, REG_INVITE, to_host, 0); switch_channel_hangup(channel, SWITCH_CAUSE_USER_CHALLENGE); } else if (code == 484 && msg->numeric_arg) { @@ -1195,7 +1195,7 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi } } - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Overlap Dial with %d %s\n", code, reason); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Overlap Dial with %d %s\n", code, reason); nua_respond(tech_pvt->nh, code, su_strdup(tech_pvt->nh->nh_home, reason), TAG_IF(to_uri, SIPTAG_CONTACT_STR(to_uri)), SIPTAG_SUPPORTED_STR(NULL), SIPTAG_ACCEPT_STR(NULL), TAG_IF(!switch_strlen_zero(max_forwards), SIPTAG_MAX_FORWARDS_STR(max_forwards)), TAG_END()); @@ -1210,7 +1210,7 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi switch_core_session_receive_message(session, msg); goto end_lock; } else { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Responding with %d [%s]\n", code, reason); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "Responding with %d [%s]\n", code, reason); if (!switch_strlen_zero(((char *) msg->pointer_arg))) { tech_pvt->local_sdp_str = switch_core_session_strdup(tech_pvt->session, (char *) msg->pointer_arg); @@ -1250,7 +1250,7 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi if (!switch_test_flag(tech_pvt, TFLAG_ANS) && !switch_test_flag(tech_pvt, TFLAG_EARLY_MEDIA)) { switch_set_flag_locked(tech_pvt, TFLAG_EARLY_MEDIA); - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_INFO, "Asked to send early media by %s\n", msg->from); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_INFO, "Asked to send early media by %s\n", msg->from); /* Transmit 183 Progress with SDP */ if (switch_channel_test_flag(channel, CF_PROXY_MODE) || switch_channel_test_flag(channel, CF_PROXY_MEDIA)) { @@ -1291,7 +1291,7 @@ static switch_status_t sofia_receive_message(switch_core_session_t *session, swi switch_channel_hangup(channel, SWITCH_CAUSE_DESTINATION_OUT_OF_ORDER); } if (tech_pvt->local_sdp_str) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_INFO, "Ring SDP:\n%s\n", tech_pvt->local_sdp_str); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_INFO, "Ring SDP:\n%s\n", tech_pvt->local_sdp_str); } } switch_channel_mark_pre_answered(channel); @@ -2284,7 +2284,7 @@ static switch_call_cause_t sofia_outgoing_channel(switch_core_session_t *session } if (!(tech_pvt = (struct private_object *) switch_core_session_alloc(nsession, sizeof(*tech_pvt)))) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "Error Creating Session\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_CRIT, "Error Creating Session\n"); goto error; } switch_mutex_init(&tech_pvt->flag_mutex, SWITCH_MUTEX_NESTED, switch_core_session_get_pool(nsession)); @@ -2303,7 +2303,7 @@ static switch_call_cause_t sofia_outgoing_channel(switch_core_session_t *session sofia_gateway_t *gateway_ptr = NULL; if (!(gw = strchr(profile_name, '/'))) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid URL\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid URL\n"); cause = SWITCH_CAUSE_INVALID_NUMBER_FORMAT; goto error; } @@ -2311,7 +2311,7 @@ static switch_call_cause_t sofia_outgoing_channel(switch_core_session_t *session *gw++ = '\0'; if (!(dest = strchr(gw, '/'))) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid URL\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid URL\n"); cause = SWITCH_CAUSE_INVALID_NUMBER_FORMAT; goto error; } @@ -2319,13 +2319,13 @@ static switch_call_cause_t sofia_outgoing_channel(switch_core_session_t *session *dest++ = '\0'; if (!(gateway_ptr = sofia_reg_find_gateway(gw))) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid Gateway\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid Gateway\n"); cause = SWITCH_CAUSE_INVALID_NUMBER_FORMAT; goto error; } if (gateway_ptr->status != SOFIA_GATEWAY_UP) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Gateway is down!\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Gateway is down!\n"); cause = SWITCH_CAUSE_NETWORK_OUT_OF_ORDER; sofia_reg_release_gateway(gateway_ptr); gateway_ptr = NULL; @@ -2357,7 +2357,7 @@ static switch_call_cause_t sofia_outgoing_channel(switch_core_session_t *session } if (tech_pvt->transport != gateway_ptr->register_transport) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "You are trying to use a different transport type for this gateway (overriding the register-transport), this is unsupported!\n"); cause = SWITCH_CAUSE_DESTINATION_OUT_OF_ORDER; goto error; @@ -2386,7 +2386,7 @@ static switch_call_cause_t sofia_outgoing_channel(switch_core_session_t *session if (gateway_ptr->vars) { switch_event_header_t *hp; for(hp = gateway_ptr->vars->headers; hp; hp = hp->next) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s setting variable [%s]=[%s]\n", + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s setting variable [%s]=[%s]\n", switch_channel_get_name(nchannel), hp->name, hp->value); switch_channel_set_variable(nchannel, hp->name, hp->value); } @@ -2394,14 +2394,14 @@ static switch_call_cause_t sofia_outgoing_channel(switch_core_session_t *session } else { if (!(dest = strchr(profile_name, '/'))) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid URL\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid URL\n"); cause = SWITCH_CAUSE_INVALID_NUMBER_FORMAT; goto error; } *dest++ = '\0'; if (!(profile = sofia_glue_find_profile(profile_name))) { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid Profile\n"); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_ERROR, "Invalid Profile\n"); cause = SWITCH_CAUSE_DESTINATION_OUT_OF_ORDER; goto error; } @@ -2421,7 +2421,7 @@ static switch_call_cause_t sofia_outgoing_channel(switch_core_session_t *session tech_pvt->dest = switch_core_session_strdup(nsession, buf); tech_pvt->local_url = switch_core_session_sprintf(nsession, "%s@%s", dest, host); } else { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Cannot locate registered user %s@%s\n", dest, host); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Cannot locate registered user %s@%s\n", dest, host); cause = SWITCH_CAUSE_USER_NOT_REGISTERED; goto error; } @@ -2433,7 +2433,7 @@ static switch_call_cause_t sofia_outgoing_channel(switch_core_session_t *session tech_pvt->local_url = switch_core_session_sprintf(nsession, "%s@%s", dest, profile_name); host = profile_name; } else { - switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Cannot locate registered user %s@%s\n", dest, profile_name); + switch_core_session_log_printf(session, SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "Cannot locate registered user %s@%s\n", dest, profile_name); cause = SWITCH_CAUSE_USER_NOT_REGISTERED; goto error; }
I like alternate version because it does not limit the scope of the special logging to sessions. It can then be used to aggregate logging on any common filterable item. On Mon, Dec 15, 2008 at 8:26 AM, <stkn@freeswitch.org> wrote:
Hi,
the following series of patches adds a per-session logging capability (patch 1) and converts a part of mod_sofia over to use the new functions as an example (patch 2).
Note: This is one of two possible ways to implement the feature... (see below)
Why?: Some of "us" are running fs with high call volumes and turning on debugging globally causes massive amounts of space used and reduced performance. This patch extends the logging api to be able to change the log level for e.g. a single session (either from the dialplan or via API command / C API) for diagnosing problems.
How?: The core patch adds a couple of new functions:
switch_core_session_log_printf(switch_core_session_t *, ...) switch_core_session_set_loglevel() switch_core_session_get_loglevel()
A new API command "uuid_loglevel <uuid> <level>" (mod_commands.c) and a dialplan app "session_loglevel" (mod_dptools.c part of the core patch) are included.
The default loglevel of a session is the current global log level.
All instances of switch_log_printf() that log session-specific messages need to be converted to the new log function for this to be useful! (The second patch has the changes for mod_sofia.c)
Alternative implementation:
There's a second way to implement this feature, without adding another log_printf function:
switch_log_printf has a "userdata" parameter that is currently unused, which could be used to pass an additional value (e.g. a session) by adding additional SWITCH_*_LOG helper macros. A session log call could look like this:
switch_log_printf(SWITCH_SESSION_LOG(session), SWITCH_LOG_DEBUG, "I'm a session debug message\n");
Pro: - Can be extended for other type of log actions (e.g. if we want to implement even more fine-grained logging, per-module etc.) without adding more switch_*_log_printf functions
Con: - More work for switch_log_printf()
Now it's up to you to discuss which way we want to go and if this feature is deemed useful :P
Stefan
P.S.: The patches are available via http too:
http://oss.axsentis.de/people/stkn/freeswitch/fs-r10758-session_loglevel.pat...
http://oss.axsentis.de/people/stkn/freeswitch/fs-r10758-session_loglevel-con...
Diffstat of the core patch:
include/private/switch_core_pvt.h | 1 include/switch_core.h | 15 ++++++++++ include/switch_log.h | 18 +++++++++++++ mod/applications/mod_commands/mod_commands.c | 37 +++++++++++++++++++++++++++ mod/applications/mod_dptools/mod_dptools.c | 19 +++++++++++++ switch_core_session.c | 15 ++++++++++ switch_log.c | 34 ++++++++++++++++++++---- 7 files changed, 133 insertions(+), 6 deletions(-)
-- Stefan Knoblich Systemadministrator
axsentis GmbH Eupener Strasse 74 50933 Köln
Tel: 0180 - 506 705 521* Fax: 0180 - 506 705 529*
E-Mail: s.knoblich@axsentis.de Web: www.axsentis.de
Eingetragen beim AG Köln: HR B 56238 UST-ID: DE244977565 Gesellschafter-Geschäftsführer: Yan Lecomte, Eduard Schlein, Apostolos Varsamis
*14ct/min aus dem Festnetz der T-Com | dtms
_______________________________________________ Freeswitch-dev mailing list Freeswitch-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ AIM: anthm MSN:anthony_minessale@hotmail.com <MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com<PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <sip%3A888@conference.freeswitch.org> iax:guest@conference.freeswitch.org/888 googletalk:conf+888@conference.freeswitch.org<googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:213-799-1400
Yeah on second thought that way makes more sense and is a little more elegant. I'll post an updated patchset when i'm done. Am Monday 15 December 2008 schrieb Anthony Minessale:
I like alternate version because it does not limit the scope of the special logging to sessions. It can then be used to aggregate logging on any common filterable item.
On Mon, Dec 15, 2008 at 8:26 AM, <stkn@freeswitch.org> wrote:
Hi,
the following series of patches adds a per-session logging capability (patch 1) and converts a part of mod_sofia over to use the new functions as an example (patch 2).
Note: This is one of two possible ways to implement the feature... (see below)
Why?: Some of "us" are running fs with high call volumes and turning on debugging globally causes massive amounts of space used and reduced performance. This patch extends the logging api to be able to change the log level for e.g. a single session (either from the dialplan or via API command / C API) for diagnosing problems.
How?: The core patch adds a couple of new functions:
switch_core_session_log_printf(switch_core_session_t *, ...) switch_core_session_set_loglevel() switch_core_session_get_loglevel()
A new API command "uuid_loglevel <uuid> <level>" (mod_commands.c) and a dialplan app "session_loglevel" (mod_dptools.c part of the core patch) are included.
The default loglevel of a session is the current global log level.
All instances of switch_log_printf() that log session-specific messages need to be converted to the new log function for this to be useful! (The second patch has the changes for mod_sofia.c)
Alternative implementation:
There's a second way to implement this feature, without adding another log_printf function:
switch_log_printf has a "userdata" parameter that is currently unused, which could be used to pass an additional value (e.g. a session) by adding additional SWITCH_*_LOG helper macros. A session log call could look like this:
switch_log_printf(SWITCH_SESSION_LOG(session), SWITCH_LOG_DEBUG, "I'm a session debug message\n");
Pro: - Can be extended for other type of log actions (e.g. if we want to implement even more fine-grained logging, per-module etc.) without adding more switch_*_log_printf functions
Con: - More work for switch_log_printf()
Now it's up to you to discuss which way we want to go and if this feature is deemed useful :P
Stefan
P.S.: The patches are available via http too:
http://oss.axsentis.de/people/stkn/freeswitch/fs-r10758-session_loglevel.pat...
http://oss.axsentis.de/people/stkn/freeswitch/fs-r10758-session_loglevel-con...
Diffstat of the core patch:
include/private/switch_core_pvt.h | 1 include/switch_core.h | 15 ++++++++++ include/switch_log.h | 18 +++++++++++++ mod/applications/mod_commands/mod_commands.c | 37 +++++++++++++++++++++++++++ mod/applications/mod_dptools/mod_dptools.c | 19 +++++++++++++ switch_core_session.c | 15 ++++++++++ switch_log.c | 34 ++++++++++++++++++++---- 7 files changed, 133 insertions(+), 6 deletions(-)
-- Stefan Knoblich Systemadministrator
axsentis GmbH Eupener Strasse 74 50933 Köln
Tel: 0180 - 506 705 521* Fax: 0180 - 506 705 529*
E-Mail: s.knoblich@axsentis.de Web: www.axsentis.de
Eingetragen beim AG Köln: HR B 56238 UST-ID: DE244977565 Gesellschafter-Geschäftsführer: Yan Lecomte, Eduard Schlein, Apostolos Varsamis
*14ct/min aus dem Festnetz der T-Com | dtms
_______________________________________________ Freeswitch-dev mailing list Freeswitch-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/
AIM: anthm MSN:anthony_minessale@hotmail.com <MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com<PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <sip%3A888@conference.freeswitch.org> iax:guest@conference.freeswitch.org/888 googletalk:conf+888@conference.freeswitch.org<googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:213-799-1400
-- Stefan Knoblich Systemadministrator axsentis GmbH Eupener Strasse 74 50933 Köln Tel: 0180 - 506 705 521* Fax: 0180 - 506 705 529* E-Mail: s.knoblich@axsentis.de Web: www.axsentis.de Eingetragen beim AG Köln: HR B 56238 UST-ID: DE244977565 Gesellschafter-Geschäftsführer: Yan Lecomte, Eduard Schlein, Apostolos Varsamis *14ct/min aus dem Festnetz der T-Com | dtms
participants (3)
-
Anthony Minessale
-
Stefan Knoblich
-
stkn＠freeswitch.org