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

@@ -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

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;

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");

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;
     }
 }

core/AmSipMsg.cpp

@@ -1,5 +1,6 @@
 #include <string.h>
 #include <stdlib.h>
+#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

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);

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);

core/log.h

@@ -29,6 +29,9 @@
 #define _log_h_
 
 #include <syslog.h>
+#ifdef _DEBUG
+#include <pthread.h>
+#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;							\
 	}								\
       }									\