From 75c40f15e5b69e4d84d43df4876257db9e870118 Mon Sep 17 00:00:00 2001 From: Stefan Sayer Date: Mon, 25 Aug 2008 21:41:36 +0000 Subject: [PATCH] SEMS-40: improved logging - print-msg.diff: create a string representation out of a AmSipRequest/~Reply; this can be used when an incoming message is discarded for some reason; - log-thread-id.diff: with debug builds, log the thread ID as well: the process ID doesn't really help when trying to trace a call flow; - di-arg-log.diff: when doing an DI call that fails, be more verbose about the reason (like what kind of argument is expected and what is received). Patch by Bogdan Pintea. - changed log format a li'l - added NO_THREADID_LOG compile option to disable thread id logging git-svn-id: http://svn.berlios.de/svnroot/repos/sems/trunk@1078 8eb893ce-cfd4-0310-b710-fb5ebe64c474 --- Makefile.defs | 1 + core/AmArg.h | 20 +++++++---- core/AmSipDialog.cpp | 3 +- core/AmSipDispatcher.cpp | 2 +- core/AmSipMsg.cpp | 78 ++++++++++++++++++++++++++++++++++++++++ core/AmSipMsg.h | 14 +++++--- core/log.cpp | 6 +++- core/log.h | 23 +++++++++--- 8 files changed, 129 insertions(+), 18 deletions(-) diff --git a/Makefile.defs b/Makefile.defs index ccfdbed0..e7240fb1 100644 --- a/Makefile.defs +++ b/Makefile.defs @@ -21,6 +21,7 @@ CPPFLAGS += -D_DEBUG \ # -DMAX_RTP_SESSIONS=8192 \ # -DOpenSER \ # -DSUPPORT_IPV6 \ +# -DNO_THREADID_LOG \ # compile with spandsp DTMF detection? see soft-switch.org # this needs a fairly new version of spandsp - tested with 0.0.4pre11 diff --git a/core/AmArg.h b/core/AmArg.h index 49caa4d6..a10e3a44 100644 --- a/core/AmArg.h +++ b/core/AmArg.h @@ -178,27 +178,33 @@ class AmArg #define isArgAObject(a) (AmArg::AObject == a.getType()) #define isArgBlob(a) (AmArg::Blob == a.getType()) +#define _THROW_TYPE_MISMATCH(exp,got) \ + do { \ + ERROR("type mismatch: expected: %d; received: %d.", AmArg::exp, got.getType()); \ + throw AmArg::TypeMismatchException(); \ + } while (0) + #define assertArgArray(a) \ if (!isArgArray(a)) \ - throw AmArg::TypeMismatchException(); + _THROW_TYPE_MISMATCH(Array,a); #define assertArgDouble(a) \ if (!isArgDouble(a)) \ - throw AmArg::TypeMismatchException(); + _THROW_TYPE_MISMATCH(Double,a); #define assertArgInt(a) \ if (!isArgInt(a)) \ - throw AmArg::TypeMismatchException(); + _THROW_TYPE_MISMATCH(Int,a); #define assertArgCStr(a) \ if (!isArgCStr(a)) \ - throw AmArg::TypeMismatchException(); + _THROW_TYPE_MISMATCH(CStr,a); #define assertArgAObject(a) \ if (!isArgAObject(a)) \ - throw AmArg::TypeMismatchException(); + _THROW_TYPE_MISMATCH(AObject,a); #define assertArgBlob(a) \ if (!isArgBlob(a)) \ - throw AmArg::TypeMismatchException(); + _THROW_TYPE_MISMATCH(Blob,a); #define assertArgStruct(a) \ if (!isArgStruct(a)) \ - throw AmArg::TypeMismatchException(); + _THROW_TYPE_MISMATCH(Struct,a); void setBorrowedPointer(ArgObject* v) { type = AObject; diff --git a/core/AmSipDialog.cpp b/core/AmSipDialog.cpp index 97408c2d..659aefed 100644 --- a/core/AmSipDialog.cpp +++ b/core/AmSipDialog.cpp @@ -181,7 +181,8 @@ void AmSipDialog::updateStatus(const AmSipReply& reply) { TransMap::iterator t_it = uac_trans.find(reply.cseq); if(t_it == uac_trans.end()){ - ERROR("could not find any transaction matching reply\n"); + ERROR("could not find any transaction matching reply: %s\n", + ((AmSipReply)reply).print().c_str()); return; } DBG("updateStatus(reply): transaction found!\n"); diff --git a/core/AmSipDispatcher.cpp b/core/AmSipDispatcher.cpp index 76ac792d..35d31834 100644 --- a/core/AmSipDispatcher.cpp +++ b/core/AmSipDispatcher.cpp @@ -45,7 +45,7 @@ void AmSipDispatcher::handleSipMsg(AmSipReply &reply) AmSipReplyEvent* ev = new AmSipReplyEvent(reply); if(!AmEventDispatcher::instance()->post(reply.local_tag,ev)){ - ERROR("could not dispatch reply\n"); + ERROR("could not dispatch reply: %s\n", reply.print().c_str()); delete ev; } } diff --git a/core/AmSipMsg.cpp b/core/AmSipMsg.cpp index 1a56281b..508c6557 100644 --- a/core/AmSipMsg.cpp +++ b/core/AmSipMsg.cpp @@ -1,5 +1,6 @@ #include #include +#include "AmUtils.h" #include "AmSipMsg.h" @@ -98,3 +99,80 @@ bool findHeader(const string& hdrs,const string& hdr_name, return false; } +/* Print Member */ +#define _PM(member, name) \ + do { \ + if (! member.empty()) \ + buf += string(name) + ":" + member + ";"; \ + } while (0) +/* Print Member in Brackets */ +#define _PMB(member, name) \ + do { \ + if (! member.empty()) \ + buf += string(name) + ":" + "[" + member + "]" + ";"; \ + } while (0) + +string AmSipRequest::print() +{ + string buf; + + _PM(serKey, "serkey"); + + _PM(r_uri, "r-uri"); + _PM(callid, "i"); + _PM(int2str(cseq), "cseq"); + _PM(from_tag, "l-tag"); + _PM(to_tag, "r-tag"); + _PM(next_hop, "nhop"); + _PMB(route, "rtset"); + _PM(contact, "m"); + + _PMB(hdrs, "hdr"); + _PM(content_type, "c"); + _PMB(body, "body"); + + _PM(user, "user"); + _PM(domain, "domain"); + _PM(from_uri, "f-uri"); + _PM(from, "from"); + _PM(to, "to"); + + _PM(dstip, "dstip"); + _PM(port, "dstport"); + + + buf = method + " [" + buf + "]"; + return buf; +} + +string AmSipReply::print() +{ + string buf; + + _PM(serKey, "serkey"); + + _PM(int2str(code), "code"); + _PMB(reason, "phrase"); + _PM(callid, "i"); + _PM(int2str(cseq), "cseq"); + _PM(local_tag, "l-tag"); + _PM(remote_tag, "r-tag"); + _PM(next_hop, "nhop"); + _PMB(route, "rtset"); + _PM(contact, "m"); + + _PMB(hdrs, "hdr"); + _PM(content_type, "c"); + _PMB(body, "body"); + + _PM(next_request_uri, "next-r-uri"); + + _PM(dstip, "dstip"); + _PM(port, "dstport"); + + buf = method + " [" + buf + "]"; + return buf; +} + +#undef _PM +#undef _PMB diff --git a/core/AmSipMsg.h b/core/AmSipMsg.h index 2b3ef7e8..4f9ec7f1 100644 --- a/core/AmSipMsg.h +++ b/core/AmSipMsg.h @@ -18,6 +18,7 @@ class _AmSipMsgInDlg string hdrs; string body; unsigned int cseq; + string callid; string dstip; // IP where Ser received the message string port; // Ser's SIP port @@ -25,23 +26,27 @@ class _AmSipMsgInDlg string serKey; _AmSipMsgInDlg() : cseq(0) { } - ~_AmSipMsgInDlg() { } + virtual ~_AmSipMsgInDlg() { }; + + virtual string print() = 0; }; /** \brief represents a SIP reply */ -struct AmSipReply : public _AmSipMsgInDlg +class AmSipReply : public _AmSipMsgInDlg { + public: unsigned int code; string reason; string next_request_uri; + /*TODO: this should be merged with request's from_/to_tag and moved above*/ string remote_tag; string local_tag; - string callid; AmSipReply() : code(0), _AmSipMsgInDlg() { } ~AmSipReply() { } + string print(); }; @@ -57,12 +62,13 @@ class AmSipRequest : public _AmSipMsgInDlg string from_uri; string from; string to; - string callid; string from_tag; string to_tag; AmSipRequest() : _AmSipMsgInDlg() { } ~AmSipRequest() { } + + string print(); }; string getHeader(const string& hdrs,const string& hdr_name); diff --git a/core/log.cpp b/core/log.cpp index e9f3af78..3d1d07a4 100644 --- a/core/log.cpp +++ b/core/log.cpp @@ -96,8 +96,12 @@ void set_log_facility(const char* facility) { void dprint(int level, const char* fct, const char* file, int line, const char* fmt, ...) { va_list ap; - + +#ifndef _DEBUG fprintf(stderr, "(%i) %s: %s (%s:%i): ",(int)getpid(), level2txt(level), fct, file, line); +#else + fprintf(stderr, "(%i) %s: " THREAD_FMT "%s (%s:%i): ",(int)getpid(), level2txt(level), THREAD_ID fct, file, line); +#endif va_start(ap, fmt); vfprintf(stderr,fmt,ap); fflush(stderr); diff --git a/core/log.h b/core/log.h index 3d0e0e68..f75b7f3a 100644 --- a/core/log.h +++ b/core/log.h @@ -29,6 +29,9 @@ #define _log_h_ #include +#ifdef _DEBUG +#include +#endif #ifdef __cplusplus extern "C" { @@ -64,6 +67,18 @@ extern "C" { #endif #define LOG_FAC_PRINT(level, args... ) log_fac_print( level, __FUNCTION__, __FILE__, __LINE__, ##args ) +#ifdef _DEBUG +#ifndef NO_THREADID_LOG +#define THREAD_FMT "[%lx] " +#define THREAD_ID (unsigned long)pthread_self(), +#endif +#endif + +#ifndef THREAD_FMT +#define THREAD_FMT "" +#define THREAD_ID +#endif + #if __GNUC__ < 3 #define _LOG(level,fmt...) LOG_PRINT(level,##fmt) #else @@ -75,16 +90,16 @@ extern "C" { else { \ switch(level){ \ case L_ERR: \ - syslog(LOG_ERR, (char*)("Error: (%s)(%s)(%i): " fmt), __FILE__, __FUNCTION__, __LINE__, ##args); \ + syslog(LOG_ERR, (char*)("ERROR: " THREAD_FMT "%s (%s:%i): " fmt), THREAD_ID __FUNCTION__, __FILE__, __LINE__, ##args); \ break; \ case L_WARN: \ - syslog(LOG_WARNING, (char*)("Warning: (%s)(%s)(%i): " fmt), __FILE__, __FUNCTION__, __LINE__, ##args); \ + syslog(LOG_WARNING, (char*)("WARNING: " THREAD_FMT "%s (%s:%i): " fmt), THREAD_ID __FUNCTION__, __FILE__, __LINE__, ##args); \ break; \ case L_INFO: \ - syslog(LOG_INFO, (char*)("Info: (%s)(%s)(%i): " fmt), __FILE__, __FUNCTION__, __LINE__, ##args); \ + syslog(LOG_INFO, (char*)("INFO: " THREAD_FMT "%s (%s:%i): " fmt), THREAD_ID __FUNCTION__, __FILE__, __LINE__, ##args); \ break; \ case L_DBG: \ - syslog(LOG_DEBUG, (char*)("Debug: (%s)(%s)(%i): " fmt), __FILE__, __FUNCTION__, __LINE__, ##args); \ + syslog(LOG_DEBUG, (char*)("DEBUG: " THREAD_FMT "%s (%s:%i): " fmt), THREAD_ID __FUNCTION__, __FILE__, __LINE__, ##args); \ break; \ } \ } \