Rework logging a bit (primarily in NG)

Creates a preliminary log tag with the call-id whenever possible.

Changes log level of underlying NG messages to DEBUG.

Does a pretty-printed dump of NG responses.

Closes #73
pull/81/head
Richard Fuchs 11 years ago
parent 015b2a9bc8
commit 016f8b3b53

@ -2978,8 +2978,7 @@ static void __call_free(void *p) {
static struct call *call_create(const str *callid, struct callmaster *m) {
struct call *c;
ilog(LOG_NOTICE, "["STR_FORMAT"] Creating new call",
STR_FMT(callid));
ilog(LOG_NOTICE, "Creating new call");
c = obj_alloc0("call", sizeof(*c), __call_free);
c->callmaster = m;
mutex_init(&c->buffer_lock);
@ -3231,7 +3230,7 @@ int call_delete_branch(struct callmaster *m, const str *callid, const str *branc
c = call_get(callid, m);
if (!c) {
ilog(LOG_INFO, "["STR_FORMAT"] Call-ID to delete not found", STR_FMT(callid));
ilog(LOG_INFO, "Call-ID to delete not found");
goto err;
}

@ -76,7 +76,7 @@ static void control_ng_incoming(struct obj *obj, str *buf, struct sockaddr_in6 *
struct control_ng *c = (void *) obj;
bencode_buffer_t bencbuf;
bencode_item_t *dict, *resp;
str cmd, cookie, data, reply, *to_send;
str cmd, cookie, data, reply, *to_send, callid;
const char *errstr;
struct msghdr mh;
struct iovec iov[3];
@ -119,11 +119,18 @@ static void control_ng_incoming(struct obj *obj, str *buf, struct sockaddr_in6 *
if (!cmd.s)
goto err_send;
log_str = g_string_sized_new(256);
g_string_append_printf(log_str, "Got valid command from %s: %.*s - ", addr, STR_FMT(&cmd));
pretty_print(dict, log_str);
ilog(LOG_INFO, "%.*s", (int) log_str->len, log_str->str);
g_string_free(log_str, TRUE);
bencode_dictionary_get_str(dict, "call-id", &callid);
log_info_str(&callid);
ilog(LOG_INFO, "Received command '"STR_FORMAT"' from %s", STR_FMT(&cmd), addr);
if (get_log_level() >= LOG_DEBUG) {
log_str = g_string_sized_new(256);
g_string_append_printf(log_str, "Dump for '"STR_FORMAT"' from %s: ", STR_FMT(&cmd), addr);
pretty_print(dict, log_str);
ilog(LOG_DEBUG, "%.*s", (int) log_str->len, log_str->str);
g_string_free(log_str, TRUE);
}
errstr = NULL;
if (!str_cmp(&cmd, "ping")) {
@ -165,15 +172,29 @@ err_send:
bencode_dictionary_add_string(resp, "result", "error");
bencode_dictionary_add_string(resp, "error-reason", errstr);
g_atomic_int_inc(&cur->errors);
goto send_resp;
cmd = STR_NULL;
send_resp:
bencode_collapse_str(resp, &reply);
to_send = &reply;
send_only:
ilog(LOG_INFO, "Returning to SIP proxy: "STR_FORMAT, STR_FMT(to_send));
if (cmd.s) {
ilog(LOG_INFO, "Replying to '"STR_FORMAT"' from %s", STR_FMT(&cmd), addr);
if (get_log_level() >= LOG_DEBUG) {
dict = bencode_decode_expect_str(&bencbuf, to_send, BENCODE_DICTIONARY);
if (dict) {
log_str = g_string_sized_new(256);
g_string_append_printf(log_str, "Response dump for '"STR_FORMAT"' to %s: ",
STR_FMT(&cmd), addr);
pretty_print(dict, log_str);
ilog(LOG_DEBUG, "%.*s", (int) log_str->len, log_str->str);
g_string_free(log_str, TRUE);
}
}
}
send_only:
ZERO(mh);
mh.msg_name = sin;
mh.msg_namelen = sizeof(*sin);

@ -115,6 +115,12 @@ static int control_stream_parse(struct control_stream *s, char *line) {
pcre_get_substring_list(line, ovec, ret, (const char ***) &out);
if (out[RE_TCP_RL_CALLID])
log_info_c_string(out[RE_TCP_RL_CALLID]);
else if (out[RE_TCP_D_CALLID])
log_info_c_string(out[RE_TCP_D_CALLID]);
if (!strcmp(out[RE_TCP_RL_CMD], "request"))
output = call_request_tcp(out, c->callmaster);
else if (!strcmp(out[RE_TCP_RL_CMD], "lookup"))

@ -82,6 +82,11 @@ static void control_udp_incoming(struct obj *obj, str *buf, struct sockaddr_in6
goto out;
}
if (out[RE_UDP_UL_CALLID])
log_info_c_string(out[RE_UDP_UL_CALLID]);
else if (out[RE_UDP_DQ_CALLID])
log_info_c_string(out[RE_UDP_DQ_CALLID]);
if (chrtoupper(out[RE_UDP_UL_CMD][0]) == 'U')
reply = call_update_udp(out, u->callmaster, addr, sin);
else if (chrtoupper(out[RE_UDP_UL_CMD][0]) == 'L')

@ -116,6 +116,13 @@ void __ilog(int prio, const char *fmt, ...) {
STR_FMT(&log_info.u.stream_fd->call->callid),
log_info.u.stream_fd->fd.localport);
break;
case LOG_INFO_STR:
snprintf(prefix, sizeof(prefix), "["STR_FORMAT"] ",
STR_FMT(log_info.u.str));
break;
case LOG_INFO_C_STRING:
snprintf(prefix, sizeof(prefix), "[%s] ", log_info.u.cstr);
break;
}
va_start(ap, fmt);
@ -127,6 +134,9 @@ void __ilog(int prio, const char *fmt, ...) {
return;
}
while (ret > 0 && msg[ret-1] == '\n')
ret--;
if ((prio & LOG_FLAG_LIMIT)) {
time_t when;
struct log_limiter_entry lle, *llep;
@ -168,7 +178,7 @@ void __ilog(int prio, const char *fmt, ...) {
infix = "... ";
}
write_log(xprio, "%s%s%s", prefix, infix, piece);
write_log(xprio, "%s%s%.*s", prefix, infix, ret, piece);
out:
free(msg);

@ -5,18 +5,24 @@
#include <syslog.h>
#include <glib.h>
#include "compat.h"
#include "str.h"
struct log_info {
union {
struct call *call;
struct stream_fd *stream_fd;
const struct call *call;
const struct stream_fd *stream_fd;
const str *str;
const char *cstr;
const void *ptr;
} u;
enum {
LOG_INFO_NONE = 0,
LOG_INFO_CALL,
LOG_INFO_STREAM_FD,
LOG_INFO_STR,
LOG_INFO_C_STRING,
} e;
};
@ -75,23 +81,41 @@ INLINE void log_info_clear() {
case LOG_INFO_STREAM_FD:
__obj_put((void *) log_info.u.stream_fd);
break;
case LOG_INFO_STR:
case LOG_INFO_C_STRING:
break;
}
log_info.e = LOG_INFO_NONE;
log_info.u.ptr = NULL;
}
INLINE void log_info_call(struct call *c) {
INLINE void log_info_call(const struct call *c) {
log_info_clear();
if (!c)
return;
log_info.e = LOG_INFO_CALL;
log_info.u.call = __obj_get((void *) c);
}
INLINE void log_info_stream_fd(struct stream_fd *sfd) {
INLINE void log_info_stream_fd(const struct stream_fd *sfd) {
log_info_clear();
if (!sfd)
return;
log_info.e = LOG_INFO_STREAM_FD;
log_info.u.stream_fd = __obj_get((void *) sfd);
}
INLINE void log_info_str(const str *s) {
log_info_clear();
if (!s || !s->s)
return;
log_info.e = LOG_INFO_STR;
log_info.u.str = s;
}
INLINE void log_info_c_string(const char *s) {
log_info_clear();
if (!s)
return;
log_info.e = LOG_INFO_C_STRING;
log_info.u.cstr = s;
}
INLINE int get_log_level(void) {
return g_atomic_int_get(&log_level);
}

Loading…
Cancel
Save