Fixed Skinny problem where not enough sanity checking was made when considering incoming skinnny messages. Improved logging flexibility.

git-svn-id: https://oreka.svn.sourceforge.net/svnroot/oreka/trunk@55 09dcff7a-b715-0410-9601-b79a96267cd0

4 files changed, 100 insertions, 59 deletions

diff --git a/orkaudio/audiocaptureplugins/voip/RtpSession.cpp b/orkaudio/audiocaptureplugins/voip/RtpSession.cpp
index 6f0795d..1283b35 100644
--- a/orkaudio/audiocaptureplugins/voip/RtpSession.cpp
+++ b/orkaudio/audiocaptureplugins/voip/RtpSession.cpp
@@ -70,7 +70,9 @@ void RtpSession::ProcessMetadataSipIncoming()
 	m_remoteParty = m_invite->m_from;
 	m_localParty = m_invite->m_to;
 	m_direction = CaptureEvent::DirIn;
-	m_capturePort.Format("%s,%d", ACE_OS::inet_ntoa(m_inviteeIp), m_inviteeTcpPort);
+	char szInviteeIp[16];
+	ACE_OS::inet_ntop(AF_INET, (void*)&m_inviteeIp, szInviteeIp, sizeof(szInviteeIp));
+	m_capturePort.Format("%s,%d", szInviteeIp, m_inviteeTcpPort);
 }
 
 void RtpSession::ProcessMetadataSipOutgoing()
@@ -78,7 +80,9 @@ void RtpSession::ProcessMetadataSipOutgoing()
 	m_remoteParty = m_invite->m_to;
 	m_localParty = m_invite->m_from;
 	m_direction = CaptureEvent::DirOut;
-	m_capturePort.Format("%s,%d", ACE_OS::inet_ntoa(m_invitorIp), m_invitorTcpPort);
+	char szInvitorIp[16];
+	ACE_OS::inet_ntop(AF_INET, (void*)&m_invitorIp, szInvitorIp, sizeof(szInvitorIp));
+	m_capturePort.Format("%s,%d", szInvitorIp, m_invitorTcpPort);
 }
 
 void RtpSession::ProcessMetadataRawRtp(RtpPacketInfoRef& rtpPacket)
@@ -114,17 +118,22 @@ void RtpSession::ProcessMetadataRawRtp(RtpPacketInfoRef& rtpPacket)
 		sourceIsLocal = false;
 	}
 
+	char szSourceIp[16];
+	ACE_OS::inet_ntop(AF_INET, (void*)&rtpPacket->m_sourceIp, szSourceIp, sizeof(szSourceIp));
+	char szDestIp[16];
+	ACE_OS::inet_ntop(AF_INET, (void*)&rtpPacket->m_destIp, szDestIp, sizeof(szDestIp));
+
 	if(sourceIsLocal)
 	{
-		m_localParty.Format("%s", ACE_OS::inet_ntoa(rtpPacket->m_sourceIp));
-		m_remoteParty.Format("%s", ACE_OS::inet_ntoa(rtpPacket->m_destIp));
-		m_capturePort.Format("%s,%d", ACE_OS::inet_ntoa(rtpPacket->m_sourceIp), rtpPacket->m_sourcePort);
+		m_localParty = szSourceIp;
+		m_remoteParty = szDestIp;
+		m_capturePort.Format("%s,%d", szSourceIp, rtpPacket->m_sourcePort);
 	}
 	else
 	{
-		m_localParty.Format("%s", ACE_OS::inet_ntoa(rtpPacket->m_destIp));
-		m_remoteParty.Format("%s", ACE_OS::inet_ntoa(rtpPacket->m_sourceIp));
-		m_capturePort.Format("%s,%d", ACE_OS::inet_ntoa(rtpPacket->m_destIp), rtpPacket->m_destPort);
+		m_localParty = szDestIp;
+		m_remoteParty = szSourceIp;
+		m_capturePort.Format("%s,%d", szDestIp, rtpPacket->m_destPort);
 	}
 }
 
@@ -189,10 +198,14 @@ void RtpSession::ProcessMetadataSkinny(RtpPacketInfoRef& rtpPacket)
 {
 	// In skinny, we know that ipAndPort are those from the CallManager.
 	// However, what we want as a capture port are IP+Port of the phone
-	m_capturePort.Format("%s,%u", ACE_OS::inet_ntoa(rtpPacket->m_sourceIp), rtpPacket->m_sourcePort);
+	char szSourceIp[16];
+	ACE_OS::inet_ntop(AF_INET, (void*)&rtpPacket->m_sourceIp, szSourceIp, sizeof(szSourceIp));
+	m_capturePort.Format("%s,%u", szSourceIp, rtpPacket->m_sourcePort);
 	if(m_capturePort.Equals(m_ipAndPort))
 	{
-		m_capturePort.Format("%s,%u", ACE_OS::inet_ntoa(rtpPacket->m_destIp), rtpPacket->m_destPort);
+		char szDestIp[16];
+		ACE_OS::inet_ntop(AF_INET, (void*)&rtpPacket->m_destIp, szDestIp, sizeof(szDestIp));
+		m_capturePort.Format("%s,%u", szDestIp, rtpPacket->m_destPort);
 	}
 }
 
@@ -317,7 +330,10 @@ RtpSessions::RtpSessions()
 
 void RtpSessions::ReportSipInvite(SipInviteInfoRef& invite)
 {
-	CStdString ipAndPort = CStdString(ACE_OS::inet_ntoa(invite->m_fromIp)) + "," + invite->m_fromRtpPort;
+	char szFromIp[16];
+	ACE_OS::inet_ntop(AF_INET, (void*)&invite->m_fromIp, szFromIp, sizeof(szFromIp));
+
+	CStdString ipAndPort = CStdString(szFromIp) + "," + invite->m_fromRtpPort;
 	std::map<CStdString, RtpSessionRef>::iterator pair;
 	
 	pair = m_byIpAndPort.find(ipAndPort);
@@ -405,7 +421,9 @@ void RtpSessions::ReportSkinnyStartMediaTransmission(SkStartMediaTransmissionStr
 		if(session->m_ipAndPort.size() == 0)
 		{
 			CStdString ipAndPort;
-			ipAndPort.Format("%s,%u", ACE_OS::inet_ntoa(startMedia->remoteIpAddr), startMedia->remoteTcpPort);
+			char szRemoteIp[16];
+			ACE_OS::inet_ntop(AF_INET, (void*)&startMedia->remoteIpAddr, szRemoteIp, sizeof(szRemoteIp));
+			ipAndPort.Format("%s,%u", szRemoteIp, startMedia->remoteTcpPort);
 			
 			pair = m_byIpAndPort.find(ipAndPort);
 			if (pair != m_byIpAndPort.end())
@@ -458,7 +476,10 @@ void RtpSessions::ReportRtpPacket(RtpPacketInfoRef& rtpPacket)
 	// Does a session exist with this source Ip+Port
 	RtpSessionRef session;
 	CStdString port = IntToString(rtpPacket->m_sourcePort);
-	CStdString ipAndPort = CStdString(ACE_OS::inet_ntoa(rtpPacket->m_sourceIp)) + "," + port;
+
+	char szSourceIp[16];
+	ACE_OS::inet_ntop(AF_INET, (void*)&rtpPacket->m_sourceIp, szSourceIp, sizeof(szSourceIp));
+	CStdString ipAndPort = CStdString(szSourceIp) + "," + port;
 	std::map<CStdString, RtpSessionRef>::iterator pair;
 
 	pair = m_byIpAndPort.find(ipAndPort);
@@ -470,7 +491,10 @@ void RtpSessions::ReportRtpPacket(RtpPacketInfoRef& rtpPacket)
 	{
 		// Does a session exist with this destination Ip+Port
 		port = IntToString(rtpPacket->m_destPort);
-		ipAndPort = CStdString(ACE_OS::inet_ntoa(rtpPacket->m_destIp)) + "," + port;
+		char szDestIp[16];
+		ACE_OS::inet_ntop(AF_INET, (void*)&rtpPacket->m_destIp, szDestIp, sizeof(szDestIp));
+		ipAndPort = CStdString(szDestIp) + "," + port;
+
 		pair = m_byIpAndPort.find(ipAndPort);
 		if (pair != m_byIpAndPort.end())
 		{
diff --git a/orkaudio/audiocaptureplugins/voip/VoIp.cpp b/orkaudio/audiocaptureplugins/voip/VoIp.cpp
index 84305e4..89298c5 100644
--- a/orkaudio/audiocaptureplugins/voip/VoIp.cpp
+++ b/orkaudio/audiocaptureplugins/voip/VoIp.cpp
@@ -34,9 +34,11 @@ extern OrkLogManager* g_logManager;
 
 #include "LogManager.h"
 
-static LoggerPtr s_log;
+static LoggerPtr s_packetLog;
+static LoggerPtr s_rtpPacketLog;
+static LoggerPtr s_sipPacketLog;
+static LoggerPtr s_skinnyPacketLog;
 static LoggerPtr s_sipExtractionLog;
-static LoggerPtr s_skinnyLog;
 time_t lastHooveringTime;
 
 VoIpConfigTopObjectRef g_VoIpConfigTopObjectRef;
@@ -156,9 +158,16 @@ bool TryRtp(EthernetHeaderStruct* ethernetHeader, IpHeaderStruct* ipHeader, UdpH
 				rtpInfo->m_timestamp = ntohl(rtpHeader->ts);
 				rtpInfo->m_payload = payload;
 
-				CStdString debug;
-				debug.Format("%s,%d seq:%u ts:%u len:%d", ACE_OS::inet_ntoa(rtpInfo->m_sourceIp), rtpInfo->m_sourcePort, ntohs(rtpHeader->seq), ntohl(rtpHeader->ts), payloadLength);
-				LOG4CXX_DEBUG(s_log, debug);
+				if(s_rtpPacketLog->isDebugEnabled())
+				{
+					CStdString debug;
+					char sourceIp[16];
+					ACE_OS::inet_ntop(AF_INET, (void*)&ipHeader->ip_src, sourceIp, sizeof(sourceIp));
+					char destIp[16];
+					ACE_OS::inet_ntop(AF_INET, (void*)&ipHeader->ip_dest, destIp, sizeof(destIp));
+					debug.Format("%s,%d %s,%d seq:%u ts:%u len:%d", sourceIp, rtpInfo->m_sourcePort, destIp, rtpInfo->m_destPort, ntohs(rtpHeader->seq), ntohl(rtpHeader->ts), payloadLength);
+					LOG4CXX_DEBUG(s_rtpPacketLog, debug);
+				}
 
 				RtpSessionsSingleton::instance()->ReportRtpPacket(rtpInfo);
 			}
@@ -183,7 +192,7 @@ bool TrySipBye(EthernetHeaderStruct* ethernetHeader, IpHeaderStruct* ipHeader, U
 			GrabToken(callIdField, info.m_callId);
 			RtpSessionsSingleton::instance()->ReportSipBye(info);
 		}
-		LOG4CXX_DEBUG(s_log, "SIP BYE");
+		LOG4CXX_DEBUG(s_sipPacketLog, "SIP BYE");
 	}
 	return result;
 }
@@ -259,7 +268,7 @@ bool TrySipInvite(EthernetHeaderStruct* ethernetHeader, IpHeaderStruct* ipHeader
 			info->m_fromIp = ipHeader->ip_src;
 			RtpSessionsSingleton::instance()->ReportSipInvite(info);
 		}
-		LOG4CXX_DEBUG(s_log, "SIP INVITE");
+		LOG4CXX_DEBUG(s_sipPacketLog, "SIP INVITE");
 	}
 	return result;
 }
@@ -276,15 +285,17 @@ void HandleSkinnyMessage(SkinnyHeaderStruct* skinnyHeader)
 	{
 	case SkStartMediaTransmission:
 		startMedia = (SkStartMediaTransmissionStruct*)skinnyHeader;
-		if(s_skinnyLog->isDebugEnabled())
+		if(s_skinnyPacketLog->isDebugEnabled())
 		{
-			debug.Format(" CallId:%u %s,%u", startMedia->conferenceId, ACE_OS::inet_ntoa(startMedia->remoteIpAddr), startMedia->remoteTcpPort);
+			char szRemoteIp[16];
+			ACE_OS::inet_ntop(AF_INET, (void*)&startMedia->remoteIpAddr, szRemoteIp, sizeof(szRemoteIp));
+			debug.Format(" CallId:%u %s,%u", startMedia->conferenceId, szRemoteIp, startMedia->remoteTcpPort);
 		}
 		RtpSessionsSingleton::instance()->ReportSkinnyStartMediaTransmission(startMedia);
 		break;
 	case SkStopMediaTransmission:
 		stopMedia = (SkStopMediaTransmissionStruct*)skinnyHeader;
-		if(s_skinnyLog->isDebugEnabled())
+		if(s_skinnyPacketLog->isDebugEnabled())
 		{
 			debug.Format(" CallId:%u", stopMedia->conferenceId);
 		}
@@ -292,7 +303,7 @@ void HandleSkinnyMessage(SkinnyHeaderStruct* skinnyHeader)
 		break;
 	case SkCallInfoMessage:
 		callInfo = (SkCallInfoStruct*)skinnyHeader;
-		if(s_skinnyLog->isDebugEnabled())
+		if(s_skinnyPacketLog->isDebugEnabled())
 		{
 			debug.Format(" CallId:%u calling:%s called:%s", callInfo->callId, callInfo->callingParty, callInfo->calledParty);
 		}
@@ -301,11 +312,11 @@ void HandleSkinnyMessage(SkinnyHeaderStruct* skinnyHeader)
 	default:
 		useful = false;
 	}
-	if(useful && s_skinnyLog->isDebugEnabled())
+	if(useful && s_skinnyPacketLog->isDebugEnabled())
 	{
 		CStdString msg = SkinnyMessageToString(skinnyHeader->messageType);
 		debug = msg + debug;
-		LOG4CXX_DEBUG(s_skinnyLog, debug);
+		LOG4CXX_INFO(s_skinnyPacketLog, debug);
 	}
 }
 
@@ -316,14 +327,6 @@ void HandlePacket(u_char *param, const struct pcap_pkthdr *header, const u_char
 	int ipHeaderLength = ipHeader->ip_hl*4;
 	u_char* ipPacketEnd = (u_char*)ipHeader + ipHeader->ip_len;
 
-	//CStdString source = ACE_OS::inet_ntoa(ipHeader->ip_src);
-	//CStdString dest = ACE_OS::inet_ntoa(ipHeader->ip_dest);
-	//CStdString debug;
-	//debug.Format("%x, %x", ethernetHeader, ipHeader);
-	//LOG4CXX_INFO(s_log, source + "-" + dest);
-
-	//LOG4CXX_DEBUG(s_log, "*");
-
 	if(ipHeader->ip_p == IPPROTO_UDP)
 	{
 		UdpHeaderStruct* udpHeader = (UdpHeaderStruct*)((char *)ipHeader + ipHeaderLength);
@@ -351,16 +354,23 @@ void HandlePacket(u_char *param, const struct pcap_pkthdr *header, const u_char
 		
 		if(ntohs(tcpHeader->source) == SKINNY_CTRL_PORT || ntohs(tcpHeader->dest) == SKINNY_CTRL_PORT)
 		{
-			SkinnyHeaderStruct* skinnyHeader = (SkinnyHeaderStruct*)((u_char*)tcpHeader + TCP_HEADER_LENGTH);
+			u_char* startTcpPayload = (u_char*)tcpHeader + TCP_HEADER_LENGTH;
+			SkinnyHeaderStruct* skinnyHeader = (SkinnyHeaderStruct*)(startTcpPayload);
 
-			// Scan all skinny message in this TCP packet
+			// Scan all skinny messages in this TCP packet
 			while(	ipPacketEnd > (u_char*)skinnyHeader && 
 					(u_char*)skinnyHeader>=((u_char*)tcpHeader + TCP_HEADER_LENGTH) &&
-					(ipPacketEnd - (u_char*)skinnyHeader) > SKINNY_MIN_MESSAGE_SIZE			)
+					(ipPacketEnd - (u_char*)skinnyHeader) > SKINNY_MIN_MESSAGE_SIZE	&&
+					skinnyHeader->len > 1 && skinnyHeader->len < 2048 &&
+					skinnyHeader->messageType >= 0x0 && skinnyHeader->messageType <= 0x13F )
 			{
-				//CStdString dbg;
-				//dbg.Format("Len:%u, Type:%x, %s", skinnyHeader->len, skinnyHeader->messageType, SkinnyMessageToString(skinnyHeader->messageType));
-				//LOG4CXX_INFO(s_log, dbg);
+				if(s_skinnyPacketLog->isDebugEnabled())
+				{
+					CStdString dbg;
+					unsigned int offset = (u_char*)skinnyHeader - startTcpPayload;
+					dbg.Format("Offset:%x Len:%u Type:%x %s", offset, skinnyHeader->len, skinnyHeader->messageType, SkinnyMessageToString(skinnyHeader->messageType));
+					LOG4CXX_DEBUG(s_skinnyPacketLog, dbg);
+				}
 				HandleSkinnyMessage(skinnyHeader);
 
 				// Point to next skinny message within this TCP packet
@@ -422,10 +432,13 @@ void Configure(DOMNode* node)
 
 void VoIp::Initialize()
 {
-	s_log = Logger::getLogger("voip");
+	s_packetLog = Logger::getLogger("packet");
+	s_rtpPacketLog = Logger::getLogger("packet.rtp");
+	s_sipPacketLog = Logger::getLogger("packet.sip");
+	s_skinnyPacketLog = Logger::getLogger("packet.skinny");
+
 	s_sipExtractionLog = Logger::getLogger("sipextraction");
-	s_skinnyLog = Logger::getLogger("skinny");
-	LOG4CXX_INFO(s_log, "Initializing VoIP plugin");
+	LOG4CXX_INFO(s_packetLog, "Initializing VoIP plugin");
 
 	// create a default config object in case it was not properly initialized by Configure
 	if(!g_VoIpConfigTopObjectRef.get())
@@ -457,17 +470,17 @@ void VoIp::Initialize()
 	char * error = NULL;
 	if (pcap_findalldevs(&devices, error) == -1)
 	{
-		LOG4CXX_ERROR(s_log, CStdString("pcap error when discovering devices: ") + error);
+		LOG4CXX_ERROR(s_packetLog, CStdString("pcap error when discovering devices: ") + error);
 	}
 	else
 	{
 		if(devices)
 		{
-			LOG4CXX_INFO(s_log, CStdString("Available pcap devices:"));
+			LOG4CXX_INFO(s_packetLog, CStdString("Available pcap devices:"));
 
 			for (pcap_if_t* device = devices; device != NULL; device = device->next)
 			{
-				LOG4CXX_INFO(s_log, CStdString("\t* ") + device->description + " " + device->name );
+				LOG4CXX_INFO(s_packetLog, CStdString("\t* ") + device->description + " " + device->name );
 				if(DLLCONFIG.m_device.Equals(device->name))
 				{
 					deviceToSniff = device;
@@ -481,11 +494,11 @@ void VoIp::Initialize()
 			{
 				if(!DLLCONFIG.m_device.IsEmpty())
 				{
-					LOG4CXX_ERROR(s_log, CStdString("pcap could not find wanted device: ") + DLLCONFIG.m_device + " please check your config file");
+					LOG4CXX_ERROR(s_packetLog, CStdString("pcap could not find wanted device: ") + DLLCONFIG.m_device + " please check your config file");
 				}
 				if(lastDevice)
 				{
-					LOG4CXX_INFO(s_log, CStdString("Defaulting to device: ") + lastDevice->name);
+					LOG4CXX_INFO(s_packetLog, CStdString("Defaulting to device: ") + lastDevice->name);
 					deviceToSniff = lastDevice;
 				}
 			}
@@ -495,17 +508,17 @@ void VoIp::Initialize()
 				if ((m_pcapHandle = pcap_open_live(deviceToSniff->name, 1500, PROMISCUOUS,
 					 500, error)) == NULL)
 				{
-					LOG4CXX_ERROR(s_log, CStdString("pcap error when opening device: ") + deviceToSniff->name);
+					LOG4CXX_ERROR(s_packetLog, CStdString("pcap error when opening device: ") + deviceToSniff->name);
 				}
 				else
 				{
-					LOG4CXX_INFO(s_log, CStdString("successfully opened device: ") + deviceToSniff->name);
+					LOG4CXX_INFO(s_packetLog, CStdString("successfully opened device: ") + deviceToSniff->name);
 				}
 			}
 		}
 		else
 		{
-			LOG4CXX_ERROR(s_log, CStdString("pcap could not find any device"));
+			LOG4CXX_ERROR(s_packetLog, CStdString("pcap could not find any device"));
 		}
 	}
 
@@ -515,18 +528,18 @@ void VoIp::Run()
 {
 	if(m_pcapHandle)
 	{
-		LOG4CXX_INFO(s_log, "Running VoIp.dll");
+		LOG4CXX_INFO(s_packetLog, "Running VoIp.dll");
 		pcap_loop(m_pcapHandle, 0, HandlePacket, NULL);
 	}
 	else
 	{
-		LOG4CXX_INFO(s_log, "No network device opened - VoIp.dll not starting");
+		LOG4CXX_INFO(s_packetLog, "No network device opened - VoIp.dll not starting");
 	}
 }
 
 void VoIp::Shutdown()
 {
-	LOG4CXX_INFO(s_log, "Shutting down VoIp.dll");
+	LOG4CXX_INFO(s_packetLog, "Shutting down VoIp.dll");
 #ifdef WIN32
 	pcap_breakloop(m_pcapHandle);
 #endif
diff --git a/orkaudio/logging-linux-template.properties b/orkaudio/logging-linux-template.properties
index 6c3cd42..497fa66 100644
--- a/orkaudio/logging-linux-template.properties
+++ b/orkaudio/logging-linux-template.properties
@@ -37,8 +37,10 @@ log4j.rootLogger=INFO, A1, stdout
 log4j.logger.reporting=INFO, messages
 log4j.logger.tapelist=INFO, tapelist
 log4j.logger.rtpringbuffer=INFO
-log4j.logger.voip=INFO
+log4j.logger.packet=INFO
+log4j.logger.packet.rtp=INFO
+log4j.logger.packet.skinny=INFO
+log4j.logger.packet.sip=INFO
 log4j.logger.rtpsessions=INFO
 log4j.logger.rtpsession=DEBUG
 log4j.logger.sipextraction=DEBUG
-log4j.logger.skinny=DEBUG
diff --git a/orkaudio/logging-template.properties b/orkaudio/logging-template.properties
index 5eb473c..8f1f745 100644
--- a/orkaudio/logging-template.properties
+++ b/orkaudio/logging-template.properties
@@ -37,8 +37,10 @@ log4j.rootLogger=INFO, A1, stdout
 log4j.logger.reporting=INFO, messages
 log4j.logger.tapelist=INFO, tapelist
 log4j.logger.rtpringbuffer=INFO
-log4j.logger.voip=INFO
+log4j.logger.packet=INFO
+log4j.logger.packet.rtp=INFO
+log4j.logger.packet.skinny=INFO
+log4j.logger.packet.sip=INFO
 log4j.logger.rtpsessions=INFO
 log4j.logger.rtpsession=DEBUG
 log4j.logger.sipextraction=DEBUG
-log4j.logger.skinny=DEBUG