Improved skinny signalling detection by taking OpenReceiveChannelAck Skinny messages into account.

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

5 files changed, 203 insertions, 117 deletions

diff --git a/orkaudio/audiocaptureplugins/voip/PacketHeaderDefs.cpp b/orkaudio/audiocaptureplugins/voip/PacketHeaderDefs.cpp
index ecf4d8e..cb9b53d 100644
--- a/orkaudio/audiocaptureplugins/voip/PacketHeaderDefs.cpp
+++ b/orkaudio/audiocaptureplugins/voip/PacketHeaderDefs.cpp
@@ -15,6 +15,14 @@ int SkinnyMessageToEnum(CStdString& msg)
 	{
 		msgEnum = SkCallInfoMessage;
 	}
+	else if (msg.CompareNoCase(SKINNY_MSG_OPEN_RECEIVE_CHANNEL_ACK) == 0)
+	{
+		msgEnum = SkOpenReceiveChannelAck;
+	}
+	else if (msg.CompareNoCase(SKINNY_MSG_CLOSE_RECEIVE_CHANNEL) == 0)
+	{
+		msgEnum = SkCloseReceiveChannel;
+	}
 	return msgEnum;
 }
 
@@ -32,6 +40,12 @@ CStdString SkinnyMessageToString(int msgEnum)
 	case SkCallInfoMessage:
 		msgString = SKINNY_MSG_CALL_INFO_MESSAGE;
 		break;
+	case SkOpenReceiveChannelAck:
+		msgString = SKINNY_MSG_OPEN_RECEIVE_CHANNEL_ACK;
+		break;
+	case SkCloseReceiveChannel:
+		msgString = SKINNY_MSG_CLOSE_RECEIVE_CHANNEL;
+		break;
 	default:
 		msgString = SKINNY_MSG_UNKN;
 	}
diff --git a/orkaudio/audiocaptureplugins/voip/PacketHeaderDefs.h b/orkaudio/audiocaptureplugins/voip/PacketHeaderDefs.h
index 4eec34d..d0e3768 100644
--- a/orkaudio/audiocaptureplugins/voip/PacketHeaderDefs.h
+++ b/orkaudio/audiocaptureplugins/voip/PacketHeaderDefs.h
@@ -90,6 +90,7 @@ typedef struct
 	//unsigned int csrc[1];		// optional CSRC list
 } RtpHeaderStruct;
 
+// Cisco Callmanager -> endpoint messages
 typedef struct
 {
 	unsigned long len;
@@ -117,6 +118,13 @@ typedef struct
 typedef struct
 {
 	SkinnyHeaderStruct header;
+	unsigned long conferenceId;
+	unsigned long passThruPartyId;
+} SkCloseReceiveChannelStruct;
+
+typedef struct
+{
+	SkinnyHeaderStruct header;
 	char callingPartyName[40];
 	char callingParty[24];
 	char calledPartyName[40];
@@ -135,6 +143,16 @@ typedef struct
 	char parties[76];
 } SkNewCallInfoStruct;
 
+// Endpoint -> Cisco Callmanager messages
+typedef struct
+{
+	SkinnyHeaderStruct header;
+	unsigned long openReceiveChannelStatus;
+	struct in_addr endpointIpAddr;
+	unsigned long endpointTcpPort;
+	unsigned long passThruPartyId;
+} SkOpenReceiveChannelAckStruct;
+
 #define SKINNY_CTRL_PORT 2000
 #define SKINNY_MIN_MESSAGE_SIZE 12
 #define SKINNY_HEADER_LENGTH 8
@@ -142,7 +160,9 @@ typedef struct
 #define SKINNY_MSG_UNKN "Unkn"
 #define SKINNY_MSG_START_MEDIA_TRANSMISSION "StartMediaTransmission"
 #define SKINNY_MSG_STOP_MEDIA_TRANSMISSION "StopMediaTransmission"
+#define SKINNY_MSG_CLOSE_RECEIVE_CHANNEL "CloseReceiveChannel"
 #define SKINNY_MSG_CALL_INFO_MESSAGE "CallInfoMessage"
+#define SKINNY_MSG_OPEN_RECEIVE_CHANNEL_ACK "OpenReceiveChannelAck"
 
 #define SKINNY_CALL_TYPE_INBOUND 1
 #define SKINNY_CALL_TYPE_OUTBOUND 2
@@ -150,9 +170,11 @@ typedef struct
 
 typedef enum
 {
+	SkOpenReceiveChannelAck = 0x0022,
 	SkStartMediaTransmission = 0x008A,
 	SkStopMediaTransmission = 0x008B,
 	SkCallInfoMessage = 0x008F,
+	SkCloseReceiveChannel = 0x0106,
 	SkUnkn = 0x0
 } SkinnyMessageEnum;
 int SkinnyMessageToEnum(CStdString& msg);
diff --git a/orkaudio/audiocaptureplugins/voip/RtpSession.cpp b/orkaudio/audiocaptureplugins/voip/RtpSession.cpp
index 190c3cb..c1c9bc8 100644
--- a/orkaudio/audiocaptureplugins/voip/RtpSession.cpp
+++ b/orkaudio/audiocaptureplugins/voip/RtpSession.cpp
@@ -44,6 +44,7 @@ RtpSession::RtpSession(CStdString& trackingId)
 	m_protocol = ProtUnkn;
 	m_numRtpPackets = 0;
 	m_started = false;
+	m_stopped = false;
 	m_rtpTimestampCorrectiveOffset = 0;
 }
 
@@ -51,12 +52,13 @@ void RtpSession::Stop()
 {
 	LOG4CXX_INFO(m_log, m_trackingId + ": " + m_capturePort + " Session stop");
 
-	if(m_started)
+	if(m_started && !m_stopped)
 	{
 		CaptureEventRef stopEvent(new CaptureEvent);
 		stopEvent->m_type = CaptureEvent::EtStop;
 		stopEvent->m_timestamp = time(NULL);
 		g_captureEventCallBack(stopEvent, m_capturePort);
+		m_stopped = true;
 	}
 }
 
@@ -508,7 +510,7 @@ void RtpSessions::ReportSipBye(SipByeInfo bye)
 
 void RtpSessions::ReportSkinnyCallInfo(SkCallInfoStruct* callInfo, IpHeaderStruct* ipHeader)
 {
-	CStdString callId = IntToString(callInfo->callId);
+	CStdString callId = GenerateSkinnyCallId(ipHeader->ip_dest, callInfo->callId);
 	std::map<CStdString, RtpSessionRef>::iterator pair;
 	pair = m_byCallId.find(callId);
 
@@ -560,129 +562,150 @@ void RtpSessions::ReportSkinnyCallInfo(SkCallInfoStruct* callInfo, IpHeaderStruc
 
 }
 
-void RtpSessions::ReportSkinnyStartMediaTransmission(SkStartMediaTransmissionStruct* startMedia, IpHeaderStruct* ipHeader)
+RtpSessionRef RtpSessions::findByEndpointIp(struct in_addr endpointIpAddr)
 {
-	// Lookup by callId
 	RtpSessionRef session;
-	//CStdString callId = IntToString(startMedia->conferenceId);
 	std::map<CStdString, RtpSessionRef>::iterator pair;
 
-	//if(callId.Equals("0"))
-	//{
-		// Ok this seems to be CallManager 3.3 or older, Conference ID field is not populated
-		// We need to find the CallInfo with the same endpoint IP address
-		for(pair = m_byCallId.begin(); pair != m_byCallId.end(); pair++)
-		{
-			RtpSessionRef tmpSession = pair->second;
+	// Scan all sessions and try to find a session on the same IP endpoint
+	for(pair = m_byCallId.begin(); pair != m_byCallId.end(); pair++)
+	{
+		RtpSessionRef tmpSession = pair->second;
 
-			if((unsigned int)tmpSession->m_endPointIp.s_addr == (unsigned int)ipHeader->ip_dest.s_addr)
-			{
-				if(tmpSession->m_ipAndPort.size() == 0)
-				{
-					session = tmpSession;
-					// The "Call ID" between StartMediaTransmission and StopMediaTransmission 
-					// is represented by either PassThruPartyId or conferenceId field.
-					// So let's move the session within the callId map.
-					// 1. remove it from the map
-					m_byCallId.erase(session->m_callId);
-					// 2. add it back with new CallId
-					CStdString newCallId;
-					if(startMedia->passThruPartyId)
-					{
-						newCallId = IntToString(startMedia->passThruPartyId);
-					}
-					else
-					{
-						newCallId = IntToString(startMedia->conferenceId);
-					}
-					CStdString oldCallId = session->m_callId;
-					session->m_callId = newCallId;
-					m_byCallId.insert(std::make_pair(newCallId, session));
-
-					if(m_log->isInfoEnabled())
-					{
-						CStdString logMsg;
-						logMsg.Format("%s: Skinny StartMedia: callId %s becomes %s", session->m_trackingId, oldCallId, newCallId);
-						LOG4CXX_INFO(m_log, logMsg);
-					}
-					break;
-				}
-				else
-				{
-					// The session has already had a StartMediaTransmission message.
-				}
-			}
+		if((unsigned int)tmpSession->m_endPointIp.s_addr == (unsigned int)endpointIpAddr.s_addr)
+		{
+			session = tmpSession;
+			break;
 		}
-	//}
-	//else
-	//{
-		// CallManager 4 or newer
-	//	pair = m_byCallId.find(callId);
-	//	if (pair != m_byCallId.end())
-	//	{
-	//		session = pair->second;
-	//	}
-	//}
-
-	if (session.get() != NULL)
-	{
-		// Session found
-		if(session->m_ipAndPort.size() == 0)
+	}
+	return session;
+}
+
+void RtpSessions::ChangeCallId(RtpSessionRef& session, unsigned int newId)
+{
+	if(newId)
+	{
+		CStdString newCallId = GenerateSkinnyCallId(session->m_endPointIp, newId);
+		CStdString oldCallId = session->m_callId;
+		m_byCallId.erase(oldCallId);
+		session->m_callId = newCallId;
+		m_byCallId.insert(std::make_pair(newCallId, session));
+
+		if(m_log->isInfoEnabled())
 		{
-			CStdString ipAndPort;
-			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())
-			{
-				// A session exists on the same IP+port, stop old session
-				RtpSessionRef session = pair->second;
-				Stop(session);
-			}
+			CStdString logMsg;
+			logMsg.Format("%s: callId %s becomes %s", session->m_trackingId, oldCallId, newCallId);
+			LOG4CXX_INFO(m_log, logMsg);
+		}
+	}
+}
 
-			if(m_log->isInfoEnabled())
-			{
-				char szEndPointIp[16];
-				ACE_OS::inet_ntop(AF_INET, (void*)&session->m_endPointIp, szEndPointIp, sizeof(szEndPointIp));
-				CStdString logMsg;
-				logMsg.Format("%s: Skinny StartMedia: callId %s is on %s  endpoint:%s", session->m_trackingId, session->m_callId, ipAndPort, szEndPointIp);
-				LOG4CXX_INFO(m_log, logMsg);
-			}
 
-			session->m_ipAndPort = ipAndPort;
-			m_byIpAndPort.insert(std::make_pair(session->m_ipAndPort, session));
+void RtpSessions::SetMediaAddress(RtpSessionRef& session, struct in_addr mediaIp, unsigned short mediaPort)
+{
+	CStdString ipAndPort;
+	char szMediaIp[16];
+	ACE_OS::inet_ntop(AF_INET, (void*)&mediaIp, szMediaIp, sizeof(szMediaIp));
+	ipAndPort.Format("%s,%u", szMediaIp, mediaPort);
+	
+	std::map<CStdString, RtpSessionRef>::iterator pair = m_byIpAndPort.find(ipAndPort);
+	if (pair != m_byIpAndPort.end())
+	{
+		// A session exists on the same IP+port, stop old session
+		RtpSessionRef session = pair->second;
+		Stop(session);
+	}
 
-			CStdString numSessions = IntToString(m_byIpAndPort.size());
-			LOG4CXX_DEBUG(m_log, CStdString("ByIpAndPort: ") + numSessions);
+	if(m_log->isInfoEnabled())
+	{
+		char szEndPointIp[16];
+		ACE_OS::inet_ntop(AF_INET, (void*)&session->m_endPointIp, szEndPointIp, sizeof(szEndPointIp));
+		CStdString logMsg;
+		logMsg.Format("%s: callId %s media address:%s  endpoint:%s", session->m_trackingId, session->m_callId, ipAndPort, szEndPointIp);
+		LOG4CXX_INFO(m_log, logMsg);
+	}
+
+	session->m_ipAndPort = ipAndPort;
+	m_byIpAndPort.insert(std::make_pair(session->m_ipAndPort, session));
+
+	CStdString numSessions = IntToString(m_byIpAndPort.size());
+	LOG4CXX_DEBUG(m_log, CStdString("ByIpAndPort: ") + numSessions);
+}
+
+CStdString RtpSessions::GenerateSkinnyCallId(struct in_addr endpointIp, unsigned int callId)
+{
+	char szEndPointIp[16];
+	ACE_OS::inet_ntop(AF_INET, (void*)&endpointIp, szEndPointIp, sizeof(szEndPointIp));
+	CStdString skinnyCallId;
+	skinnyCallId.Format("%u@%s", callId, szEndPointIp);
+	return skinnyCallId;
+}
+
+void RtpSessions::ReportSkinnyOpenReceiveChannelAck(SkOpenReceiveChannelAckStruct* openReceive)
+{
+	RtpSessionRef session = findByEndpointIp(openReceive->endpointIpAddr);
+	if(session.get())
+	{
+		if(session->m_ipAndPort.size() == 0)
+		{
+			ChangeCallId(session, openReceive->passThruPartyId);
+			SetMediaAddress(session, openReceive->endpointIpAddr, openReceive->endpointTcpPort);
 		}
 		else
 		{
-			// The session has already had a StartMediaTransmission message.
+			LOG4CXX_DEBUG(m_log, session->m_trackingId + ": OpenReceiveChannelAck: session already got media address signalling");
 		}
 	}
 	else
 	{
 		// Discard because we have not seen any CallInfo Message before
+		LOG4CXX_INFO(m_log, "Skinny OpenReceiveChannelAck without a CallInfoMessage");
 	}
 }
 
-void RtpSessions::ReportSkinnyStopMediaTransmission(SkStopMediaTransmissionStruct* stopMedia)
+
+void RtpSessions::ReportSkinnyStartMediaTransmission(SkStartMediaTransmissionStruct* startMedia, IpHeaderStruct* ipHeader)
 {
-	CStdString callId;
-	if(stopMedia->conferenceId == 0)
+	RtpSessionRef session = findByEndpointIp(ipHeader->ip_dest);
+	if(session.get())
 	{
-		// CallManager 3.3 or older, see explanation in ReportSkinnyStartMediaTransmission
-		callId = IntToString(stopMedia->passThruPartyId);
+		if(session->m_ipAndPort.size() == 0)
+		{
+			ChangeCallId(session, startMedia->passThruPartyId);
+			SetMediaAddress(session, startMedia->remoteIpAddr, startMedia->remoteTcpPort);
+		}
+		else
+		{
+			LOG4CXX_DEBUG(m_log, session->m_trackingId + ": StartMediaTransmission: session already got media address signalling");
+		}
 	}
 	else
 	{
-		// CallManager 4 or later
-		callId = IntToString(stopMedia->conferenceId);
+		// Discard because we have not seen any CallInfo Message before
+		LOG4CXX_INFO(m_log, "Skinny StartMediaTransmission without a CallInfoMessage");
+	}
+}
+
+void RtpSessions::ReportSkinnyStopMediaTransmission(SkStopMediaTransmissionStruct* stopMedia, IpHeaderStruct* ipHeader)
+{
+	CStdString conferenceId;
+	CStdString passThruPartyId;
+	CStdString skinnyCallId;
+	std::map<CStdString, RtpSessionRef>::iterator pair = m_byCallId.end();
+
+	// Try to locate the session using either conferenceId or passThruPartyId
+	if(stopMedia->conferenceId != 0)
+	{
+		conferenceId = IntToString(stopMedia->conferenceId);
+		skinnyCallId = GenerateSkinnyCallId(ipHeader->ip_dest, stopMedia->conferenceId);
+		pair = m_byCallId.find(skinnyCallId);
+	}
+	if(pair == m_byCallId.end() && stopMedia->passThruPartyId != 0)
+	{
+		passThruPartyId = IntToString(stopMedia->passThruPartyId);
+		skinnyCallId = GenerateSkinnyCallId(ipHeader->ip_dest, stopMedia->passThruPartyId);
+		pair = m_byCallId.find(skinnyCallId);
 	}
-	std::map<CStdString, RtpSessionRef>::iterator pair;
-	pair = m_byCallId.find(callId);
 
 	if (pair != m_byCallId.end())
 	{
@@ -692,7 +715,7 @@ void RtpSessions::ReportSkinnyStopMediaTransmission(SkStopMediaTransmissionStruc
 		if(m_log->isInfoEnabled())
 		{
 			CStdString logMsg;
-			logMsg.Format("%s: Skinny StopMedia", session->m_trackingId);
+			logMsg.Format("%s: Skinny StopMedia conferenceId:%s passThruPartyId:%s", session->m_trackingId, conferenceId, passThruPartyId);
 			LOG4CXX_INFO(m_log, logMsg);
 		}
 
diff --git a/orkaudio/audiocaptureplugins/voip/RtpSession.h b/orkaudio/audiocaptureplugins/voip/RtpSession.h
index dc1fcae..a745c38 100644
--- a/orkaudio/audiocaptureplugins/voip/RtpSession.h
+++ b/orkaudio/audiocaptureplugins/voip/RtpSession.h
@@ -120,10 +120,12 @@ private:
 	LoggerPtr m_log;
 	CStdString m_capturePort;
 	bool m_started;
+	bool m_stopped;
 	int m_rtpTimestampCorrectiveOffset;
 };
 typedef boost::shared_ptr<RtpSession> RtpSessionRef;
 
+//===================================================================
 class RtpSessions
 {
 public:
@@ -134,10 +136,16 @@ public:
 	void ReportSipBye(SipByeInfo bye);
 	void ReportSkinnyCallInfo(SkCallInfoStruct*, IpHeaderStruct* ipHeader);
 	void ReportSkinnyStartMediaTransmission(SkStartMediaTransmissionStruct*, IpHeaderStruct* ipHeader);
-	void ReportSkinnyStopMediaTransmission(SkStopMediaTransmissionStruct*);
+	void ReportSkinnyStopMediaTransmission(SkStopMediaTransmissionStruct*, IpHeaderStruct* ipHeader);
+	void ReportSkinnyOpenReceiveChannelAck(SkOpenReceiveChannelAckStruct*);
 	void ReportRtpPacket(RtpPacketInfoRef& rtpPacket);
 	void Hoover(time_t now);
 private:
+	RtpSessionRef findByEndpointIp(struct in_addr);
+	void ChangeCallId(RtpSessionRef& session, unsigned int newId);
+	void SetMediaAddress(RtpSessionRef& session, struct in_addr mediaIp, unsigned short mediaPort);
+	CStdString GenerateSkinnyCallId(struct in_addr endpointIp, unsigned int callId);
+
 	std::map<CStdString, RtpSessionRef> m_byIpAndPort;
 	std::map<CStdString, RtpSessionRef> m_byCallId;
 	LoggerPtr m_log;
diff --git a/orkaudio/audiocaptureplugins/voip/VoIp.cpp b/orkaudio/audiocaptureplugins/voip/VoIp.cpp
index c2c51a2..039adb7 100644
--- a/orkaudio/audiocaptureplugins/voip/VoIp.cpp
+++ b/orkaudio/audiocaptureplugins/voip/VoIp.cpp
@@ -171,9 +171,9 @@ bool TryRtp(EthernetHeaderStruct* ethernetHeader, IpHeaderStruct* ipHeader, UdpH
 
 				if(s_rtpPacketLog->isDebugEnabled())
 				{
-					CStdString debug;
-					rtpInfo->ToString(debug);
-					LOG4CXX_DEBUG(s_rtpPacketLog, debug);
+					CStdString logMsg;
+					rtpInfo->ToString(logMsg);
+					LOG4CXX_DEBUG(s_rtpPacketLog, logMsg);
 				}
 				if(payloadLength < 800)		// sanity check, speech RTP payload should always be smaller
 				{
@@ -185,13 +185,13 @@ bool TryRtp(EthernetHeaderStruct* ethernetHeader, IpHeaderStruct* ipHeader, UdpH
 				// unsupported CODEC
 				if(s_rtpPacketLog->isDebugEnabled())
 				{
-					CStdString debug;
+					CStdString logMsg;
 					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("Unsupported codec:%x  src:%s dst:%s", rtpHeader->pt, sourceIp, destIp);
-					LOG4CXX_DEBUG(s_rtpPacketLog, debug);
+					logMsg.Format("Unsupported codec:%x  src:%s dst:%s", rtpHeader->pt, sourceIp, destIp);
+					LOG4CXX_DEBUG(s_rtpPacketLog, logMsg);
 				}
 			}
 		}
@@ -335,47 +335,66 @@ bool TrySipInvite(EthernetHeaderStruct* ethernetHeader, IpHeaderStruct* ipHeader
 void HandleSkinnyMessage(SkinnyHeaderStruct* skinnyHeader, IpHeaderStruct* ipHeader)
 {
 	bool useful = true;
-	CStdString debug;
+	CStdString logMsg;
+	
 	SkStartMediaTransmissionStruct* startMedia;
 	SkStopMediaTransmissionStruct* stopMedia;
 	SkCallInfoStruct* callInfo;
+	SkOpenReceiveChannelAckStruct* openReceiveAck;
+
+	char szEndpointIp[16];
+	struct in_addr endpointIp = ipHeader->ip_dest;	// most of the interesting skinny messages are CCM -> phone
 
 	switch(skinnyHeader->messageType)
 	{
 	case SkStartMediaTransmission:
 		startMedia = (SkStartMediaTransmissionStruct*)skinnyHeader;
-		if(s_skinnyPacketLog->isDebugEnabled())
+		if(s_skinnyPacketLog->isInfoEnabled())
 		{
 			char szRemoteIp[16];
 			ACE_OS::inet_ntop(AF_INET, (void*)&startMedia->remoteIpAddr, szRemoteIp, sizeof(szRemoteIp));
-			debug.Format(" CallId:%u PassThru:%u %s,%u", startMedia->conferenceId, startMedia->passThruPartyId, szRemoteIp, startMedia->remoteTcpPort);
+			logMsg.Format(" CallId:%u PassThru:%u media address:%s,%u", startMedia->conferenceId, startMedia->passThruPartyId, szRemoteIp, startMedia->remoteTcpPort);
 		}
 		RtpSessionsSingleton::instance()->ReportSkinnyStartMediaTransmission(startMedia, ipHeader);
 		break;
 	case SkStopMediaTransmission:
+	case SkCloseReceiveChannel:
+		// StopMediaTransmission and CloseReceiveChannel have the same definition, treat them the same for now.
 		stopMedia = (SkStopMediaTransmissionStruct*)skinnyHeader;
-		if(s_skinnyPacketLog->isDebugEnabled())
+		if(s_skinnyPacketLog->isInfoEnabled())
 		{
-			debug.Format(" CallId:%u PassThru:%u", stopMedia->conferenceId, stopMedia->passThruPartyId);
+			logMsg.Format(" ConferenceId:%u PassThruPartyId:%u", stopMedia->conferenceId, stopMedia->passThruPartyId);
 		}
-		RtpSessionsSingleton::instance()->ReportSkinnyStopMediaTransmission(stopMedia);
+		RtpSessionsSingleton::instance()->ReportSkinnyStopMediaTransmission(stopMedia, ipHeader);
 		break;
 	case SkCallInfoMessage:
 		callInfo = (SkCallInfoStruct*)skinnyHeader;
-		if(s_skinnyPacketLog->isDebugEnabled())
+		if(s_skinnyPacketLog->isInfoEnabled())
 		{
-			debug.Format(" CallId:%u calling:%s called:%s", callInfo->callId, callInfo->callingParty, callInfo->calledParty);
+			logMsg.Format(" CallId:%u calling:%s called:%s", callInfo->callId, callInfo->callingParty, callInfo->calledParty);
 		}
 		RtpSessionsSingleton::instance()->ReportSkinnyCallInfo(callInfo, ipHeader);
 		break;
+	case SkOpenReceiveChannelAck:
+		openReceiveAck = (SkOpenReceiveChannelAckStruct*)skinnyHeader;
+		if(s_skinnyPacketLog->isInfoEnabled())
+		{
+			char szMediaIp[16];
+			ACE_OS::inet_ntop(AF_INET, (void*)&openReceiveAck->endpointIpAddr, szMediaIp, sizeof(szMediaIp));
+			logMsg.Format(" PassThru:%u media address:%s,%u", openReceiveAck->passThruPartyId, szMediaIp, openReceiveAck->endpointTcpPort);
+		}
+		endpointIp = ipHeader->ip_src;	// this skinny message is phone -> CCM
+		RtpSessionsSingleton::instance()->ReportSkinnyOpenReceiveChannelAck(openReceiveAck);
+		break;
 	default:
 		useful = false;
 	}
-	if(useful && s_skinnyPacketLog->isDebugEnabled())
+	if(useful && s_skinnyPacketLog->isInfoEnabled())
 	{
 		CStdString msg = SkinnyMessageToString(skinnyHeader->messageType);
-		debug = msg + debug;
-		LOG4CXX_INFO(s_skinnyPacketLog, debug);
+		ACE_OS::inet_ntop(AF_INET, (void*)&endpointIp, szEndpointIp, sizeof(szEndpointIp));
+		logMsg = "processed " + msg + logMsg + " endpoint:" + szEndpointIp;
+		LOG4CXX_INFO(s_skinnyPacketLog, logMsg);
 	}
 }