unified and cleaned up debug log

SIP message processing and Session event processing are now
enclosed in blocks with the form

vv <type> [<callid>|<ltag>] ...  vv
^^ <type> [<callid>|<ltag>] ...  ^^

where
  <type> = M   SIP message processing
  <type> = S   Session event processing
sayer/1.4-spce2.6
Stefan Sayer 16 years ago
parent 0f3edf742b
commit 5bd402c8bd

@ -212,9 +212,9 @@ void AmB2BSession::onSipReply(const AmSipReply& reply,
TransMap::iterator t = relayed_req.find(reply.cseq);
bool fwd = (t != relayed_req.end()) && (reply.code != 100);
DBG("onSipReply: %s -> %i %s (fwd=%s)\n",
trans_method.c_str(), reply.code,reply.reason.c_str(),fwd?"true":"false");
DBG("onSipReply: content-type = %s\n",reply.content_type.c_str());
DBG("onSipReply: %s -> %i %s (fwd=%s), c-t=%s\n",
trans_method.c_str(), reply.code,reply.reason.c_str(),fwd?"true":"false",
reply.content_type.c_str());
if(fwd) {
updateRefreshMethod(reply.hdrs);
@ -254,7 +254,7 @@ void AmB2BSession::onInvite2xx(const AmSipReply& reply)
int AmB2BSession::relayEvent(AmEvent* ev)
{
DBG("AmB2BSession::relayEvent: id=%s\n",
DBG("AmB2BSession::relayEvent: to other_id='%s'\n",
other_id.c_str());
if(!other_id.empty()) {
@ -370,7 +370,7 @@ bool AmB2BSession::refresh(int flags) {
if (dlg.getStatus() != AmSipDialog::Connected)
return false;
DBG(" *** AmB2BSession::refresh *** \n");
DBG(" AmB2BSession::refresh: refreshing session\n");
// not in B2B mode
if (other_id.empty() ||
// UPDATE as refresh handled like normal session

@ -427,9 +427,8 @@ bool AmSession::processEventsCatchExceptions() {
this should be called until it returns false. */
bool AmSession::processingCycle() {
DBG("%s/%s vv %c, %s, %s, %i UACTransPending\n",
DBG("vv S [%s|%s] %s, %s, %i UACTransPending vv\n",
dlg.callid.c_str(),getLocalTag().c_str(),
processing_status == SESSION_PROCESSING_EVENTS ? 'P':'W',
AmSipDialog::status2str[dlg.getStatus()],
sess_stopped.get()?"stopped":"running",
dlg.getUACTransPending());
@ -446,9 +445,8 @@ bool AmSession::processingCycle() {
int dlg_status = dlg.getStatus();
bool s_stopped = sess_stopped.get();
DBG("%s/%s ^^ %c, %s, %s, %i UACTransPending\n",
DBG("^^ S [%s|%s] %s, %s, %i UACTransPending ^^\n",
dlg.callid.c_str(),getLocalTag().c_str(),
processing_status == SESSION_PROCESSING_EVENTS ? 'P':'W',
AmSipDialog::status2str[dlg_status],
s_stopped?"stopped":"running",
dlg.getUACTransPending());
@ -489,9 +487,17 @@ bool AmSession::processingCycle() {
processing_status = SESSION_ENDED_DISCONNECTED;
return false; // exception occured, stop processing
}
bool res = dlg.getStatus() != AmSipDialog::Disconnected;
if (!res)
processing_status = SESSION_ENDED_DISCONNECTED;
DBG("^^ S [%s|%s] %s, %s, %i UACTransPending ^^\n",
dlg.callid.c_str(),getLocalTag().c_str(),
AmSipDialog::status2str[dlg.getStatus()],
sess_stopped.get()?"stopped":"running",
dlg.getUACTransPending());
return res;
}; break;
@ -639,7 +645,7 @@ void AmSession::process(AmEvent* ev)
{
CALL_EVENT_H(process,ev);
DBG("AmSession::process\n");
DBG("AmSession processing event\n");
if (ev->event_id == E_SYSTEM) {
AmSystemEvent* sys_ev = dynamic_cast<AmSystemEvent*>(ev);

@ -108,9 +108,6 @@ void AmSessionProcessorThread::run() {
events.processEvents();
// startup all new sessions
DBG("startup_sessions.size() == %zd [%p]\n",
startup_sessions.size(), &startup_sessions);
if (!startup_sessions.empty()) {
DBG("starting up %zd sessions\n", startup_sessions.size());
@ -118,8 +115,8 @@ void AmSessionProcessorThread::run() {
startup_sessions.begin();
it != startup_sessions.end(); it++) {
DBG("starting up [%p/ltag %s]\n",
*it, (*it)->getLocalTag().c_str());
DBG("starting up [%s|%s]: [%p]\n",
(*it)->getCallID().c_str(), (*it)->getLocalTag().c_str(),*it);
if ((*it)->startup()) {
sessions.push_back(*it); // startup successful
// make sure this session is being processed for startup events
@ -132,7 +129,7 @@ void AmSessionProcessorThread::run() {
std::vector<AmSession*> fin_sessions;
DBG("processing events for <=%zd sessions\n",
DBG("processing events for up to %zd sessions\n",
pending_process_sessions.size());
std::list<AmSession*>::iterator it=sessions.begin();
@ -176,12 +173,7 @@ void AmSessionProcessorThread::process(AmEvent* e) {
return;
}
DBG("scheduling session [%p/%s] for startup\n",
add_ev->s, add_ev->s->getCallID().c_str());
startup_sessions.push_back(add_ev->s);
DBG("%zd sessions waiting for startup [%p]\n",
startup_sessions.size(), &startup_sessions);
}
void AmSessionProcessorThread::startSession(AmSession* s) {

@ -43,14 +43,15 @@ AmSipDispatcher* AmSipDispatcher::instance()
void AmSipDispatcher::handleSipMsg(AmSipReply &reply)
{
AmSipReplyEvent* ev = new AmSipReplyEvent(reply);
if(!AmEventDispatcher::instance()->post(reply.local_tag,ev)){
if ((reply.code >= 100) && (reply.code < 300)) {
if (AmConfig::UnhandledReplyLoglevel >= 0) {
_LOG(AmConfig::UnhandledReplyLoglevel,
"unhandled prov/positive reply: %s\n", reply.print().c_str());
"unhandled SIP reply: %s\n", reply.print().c_str());
}
} else {
ERROR("unhandled reply: %s\n", reply.print().c_str());
ERROR("unhandled SIP reply: %s\n", reply.print().c_str());
}
delete ev;
}
@ -75,7 +76,8 @@ void AmSipDispatcher::handleSipMsg(AmSipRequest &req)
"Call leg/Transaction does not exist");
}
else {
ERROR("received ACK for non-existing dialog (callid=%s;remote_tag=%s;local_tag=%s)\n",
ERROR("received ACK for non-existing dialog "
"(callid=%s;remote_tag=%s;local_tag=%s)\n",
callid.c_str(),remote_tag.c_str(),local_tag.c_str());
}
}

@ -570,6 +570,9 @@ void SipCtrlInterface::handle_sip_request(const trans_ticket& tt, sip_msg* msg)
}
AmSipDispatcher::instance()->handleSipMsg(req);
DBG("^^ M [%s|%s] Ru SIP request %s handled ^^\n",
req.callid.c_str(), req.to_tag.c_str(), req.method.c_str());
}
void SipCtrlInterface::handle_sip_reply(sip_msg* msg)
@ -589,6 +592,10 @@ void SipCtrlInterface::handle_sip_reply(sip_msg* msg)
DBG("cseq = <%i>\n",reply.cseq);
AmSipDispatcher::instance()->handleSipMsg(reply);
DBG("^^ M [%s|%s] ru SIP reply %u %s handled ^^\n",
reply.callid.c_str(), reply.local_tag.c_str(),
reply.code, reply.reason.c_str());
}
void SipCtrlInterface::handle_reply_timeout(AmSipTimeoutEvent::EvType evt,

@ -94,7 +94,7 @@ sip_msg::sip_msg()
sip_msg::~sip_msg()
{
DBG("~sip_msg()\n");
// DBG("~sip_msg()\n");
delete [] buf;

@ -208,7 +208,8 @@ void udp_trsp::run()
if (SipCtrlInterface::log_raw_messages >= 0) {
_LOG(SipCtrlInterface::log_raw_messages,
"recvd msg\n--++--\n%.*s--++--\n", s_msg->len, s_msg->buf);
"vv M [|] u recvd msg via UDP vv\n--++--\n%.*s--++--\n",
s_msg->len, s_msg->buf);
}
memcpy(&s_msg->remote_ip,msg.msg_name,msg.msg_namelen);

@ -39,7 +39,7 @@
timer::~timer()
{
DBG("timer::~timer(this=%p)\n",this);
// DBG("timer::~timer(this=%p)\n",this);
}
_wheeltimer::_wheeltimer()

Loading…
Cancel
Save