--- a/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp
+++ b/media/webrtc/signaling/src/mediapipeline/MediaPipeline.cpp
@@ -4,16 +4,17 @@
* You can obtain one at http://mozilla.org/MPL/2.0/. */
// Original author: ekr@rtfm.com
#include "MediaPipeline.h"
#include "MediaStreamGraphImpl.h"
+#include <inttypes.h>
#include <math.h>
#include "nspr.h"
#include "srtp.h"
#include "VideoSegment.h"
#include "Layers.h"
#include "LayersLogging.h"
@@ -51,32 +52,35 @@
#include "webrtc/common_types.h"
#include "webrtc/common_video/libyuv/include/webrtc_libyuv.h"
#include "webrtc/common_video/include/video_frame_buffer.h"
#include "webrtc/base/bind.h"
#include "nsThreadUtils.h"
-#include "logging.h"
+#include "CSFLog.h"
// Max size given stereo is 480*2*2 = 1920 (10ms of 16-bits stereo audio at
// 48KHz)
#define AUDIO_SAMPLE_BUFFER_MAX_BYTES 480*2*2
static_assert((WEBRTC_DEFAULT_SAMPLE_RATE/100)*sizeof(uint16_t) * 2
<= AUDIO_SAMPLE_BUFFER_MAX_BYTES,
"AUDIO_SAMPLE_BUFFER_MAX_BYTES is not large enough");
using namespace mozilla;
using namespace mozilla::dom;
using namespace mozilla::gfx;
using namespace mozilla::layers;
-// Logging context
-MOZ_MTLOG_MODULE("mediapipeline")
+static const char* mpLogTag = "MediaPipeline";
+#ifdef LOGTAG
+#undef LOGTAG
+#endif
+#define LOGTAG mpLogTag
namespace mozilla {
extern mozilla::LogModule* AudioLogModule();
class VideoConverterListener
{
public:
NS_INLINE_DECL_THREADSAFE_REFCOUNTING(VideoConverterListener)
@@ -143,36 +147,35 @@ public:
}
last_img_ = serial;
// A throttling limit of 1 allows us to convert 2 frames concurrently.
// It's short enough to not build up too significant a delay, while
// giving us a margin to not cause some machines to drop every other frame.
const int32_t queueThrottlingLimit = 1;
if (mLength > queueThrottlingLimit) {
- MOZ_MTLOG(ML_DEBUG, "VideoFrameConverter " << this << " queue is full." <<
- " Throttling by throwing away a frame.");
+ CSFLogDebug(LOGTAG, "VideoFrameConverter %p queue is full. Throttling by throwing away a frame.",
+ this);
#ifdef DEBUG
++mThrottleCount;
mThrottleRecord = std::max(mThrottleCount, mThrottleRecord);
#endif
return;
}
#ifdef DEBUG
if (mThrottleCount > 0) {
- auto level = ML_DEBUG;
if (mThrottleCount > 5) {
// Log at a higher level when we have large drops.
- level = ML_INFO;
+ CSFLogInfo(LOGTAG, "VideoFrameConverter %p stopped throttling after throwing away %d frames. Longest throttle so far was %d frames.",
+ this, mThrottleCount, mThrottleRecord);
+ } else {
+ CSFLogDebug(LOGTAG, "VideoFrameConverter %p stopped throttling after throwing away %d frames. Longest throttle so far was %d frames.",
+ this, mThrottleCount, mThrottleRecord);
}
- MOZ_MTLOG(level, "VideoFrameConverter " << this << " stopped" <<
- " throttling after throwing away " << mThrottleCount <<
- " frames. Longest throttle so far was " <<
- mThrottleRecord << " frames.");
mThrottleCount = 0;
}
#endif
bool forceBlack = aForceBlack || aChunk.mFrame.GetForceBlack();
if (forceBlack) {
// Reset the last-img check.
@@ -245,17 +248,17 @@ protected:
unsigned int aVideoFrameLength,
unsigned short aWidth,
unsigned short aHeight,
VideoType aVideoType,
uint64_t aCaptureTime)
{
// check for parameter sanity
if (!aBuffer || aVideoFrameLength == 0 || aWidth == 0 || aHeight == 0) {
- MOZ_MTLOG(ML_ERROR, __FUNCTION__ << " Invalid Parameters ");
+ CSFLogError(LOGTAG, "%s Invalid Parameters", __FUNCTION__);
MOZ_ASSERT(false);
return;
}
MOZ_ASSERT(aVideoType == VideoType::kVideoI420);
const int stride_y = aWidth;
const int stride_uv = (aWidth + 1) / 2;
@@ -303,17 +306,17 @@ protected:
// Send a black image.
auto pixelData = MakeUniqueFallible<uint8_t[]>(length.value());
if (pixelData) {
// YCrCb black = 0x10 0x80 0x80
memset(pixelData.get(), 0x10, yPlaneLen.value());
// Fill Cb/Cr planes
memset(pixelData.get() + yPlaneLen.value(), 0x80, cbcrPlaneLen);
- MOZ_MTLOG(ML_DEBUG, "Sending a black video frame");
+ CSFLogDebug(LOGTAG, "Sending a black video frame");
VideoFrameConverted(Move(pixelData), length.value(),
size.width, size.height,
mozilla::kVideoI420, 0);
}
return;
}
ImageFormat format = aImage->GetFormat();
@@ -339,33 +342,34 @@ protected:
y, yStride,
cb, cbCrStride,
cr, cbCrStride,
callback_unused));
webrtc::VideoFrame i420_frame(video_frame_buffer,
0, 0, // not setting timestamps
webrtc::kVideoRotation_0);
- MOZ_MTLOG(ML_DEBUG, "Sending an I420 video frame");
+ CSFLogDebug(LOGTAG, "Sending an I420 video frame");
VideoFrameConverted(i420_frame);
return;
}
}
RefPtr<SourceSurface> surf = aImage->GetAsSourceSurface();
if (!surf) {
- MOZ_MTLOG(ML_ERROR, "Getting surface from " << Stringify(format) << " image failed");
+ CSFLogError(LOGTAG, "Getting surface from %s image failed",
+ Stringify(format).c_str());
return;
}
RefPtr<DataSourceSurface> data = surf->GetDataSurface();
if (!data) {
- MOZ_MTLOG(ML_ERROR, "Getting data surface from " << Stringify(format)
- << " image with " << Stringify(surf->GetType()) << "("
- << Stringify(surf->GetFormat()) << ") surface failed");
+ CSFLogError(LOGTAG, "Getting data surface from %s image with %s (%s) surface failed",
+ Stringify(format).c_str(), Stringify(surf->GetType()).c_str(),
+ Stringify(surf->GetFormat()).c_str());
return;
}
IntSize size = aImage->GetSize();
// these don't need to be CheckedInt, any overflow will be caught by YSIZE
int half_width = (size.width + 1) >> 1;
int half_height = (size.height + 1) >> 1;
int c_size = half_width * half_height;
@@ -378,19 +382,19 @@ protected:
auto yuv_scoped = MakeUniqueFallible<uint8[]>(buffer_size.value());
if (!yuv_scoped) {
return;
}
uint8* yuv = yuv_scoped.get();
DataSourceSurface::ScopedMap map(data, DataSourceSurface::READ);
if (!map.IsMapped()) {
- MOZ_MTLOG(ML_ERROR, "Reading DataSourceSurface from " << Stringify(format)
- << " image with " << Stringify(surf->GetType()) << "("
- << Stringify(surf->GetFormat()) << ") surface failed");
+ CSFLogError(LOGTAG, "Reading DataSourceSurface from %s image with %s (%s) surface failed",
+ Stringify(format).c_str(), Stringify(surf->GetType()).c_str(),
+ Stringify(surf->GetFormat()).c_str());
return;
}
int rv;
int cb_offset = YSIZE(size.width, size.height).value();
int cr_offset = cb_offset + c_size;
switch (surf->GetFormat()) {
case SurfaceFormat::B8G8R8A8:
@@ -406,26 +410,28 @@ protected:
rv = libyuv::RGB565ToI420(static_cast<uint8*>(map.GetData()),
map.GetStride(),
yuv, size.width,
yuv + cb_offset, half_width,
yuv + cr_offset, half_width,
size.width, size.height);
break;
default:
- MOZ_MTLOG(ML_ERROR, "Unsupported RGB video format" << Stringify(surf->GetFormat()));
+ CSFLogError(LOGTAG, "Unsupported RGB video format %s",
+ Stringify(surf->GetFormat()).c_str());
MOZ_ASSERT(PR_FALSE);
return;
}
if (rv != 0) {
- MOZ_MTLOG(ML_ERROR, Stringify(surf->GetFormat()) << " to I420 conversion failed");
+ CSFLogError(LOGTAG, "%s to I420 conversion failed",
+ Stringify(surf->GetFormat()).c_str());
return;
}
- MOZ_MTLOG(ML_DEBUG, "Sending an I420 video frame converted from " <<
- Stringify(surf->GetFormat()));
+ CSFLogDebug(LOGTAG, "Sending an I420 video frame converted from %s",
+ Stringify(surf->GetFormat()).c_str());
VideoFrameConverted(Move(yuv_scoped), buffer_size.value(), size.width, size.height, mozilla::kVideoI420, 0);
}
Atomic<int32_t, Relaxed> mLength;
RefPtr<TaskQueue> mTaskQueue;
// Written and read from the queueing thread (normally MSG).
int32_t last_img_; // serial number of last Image
@@ -589,17 +595,17 @@ MediaPipeline::MediaPipeline(const std::
MOZ_ASSERT(rtp_transport != rtcp_transport);
// PipelineTransport() will access this->sts_thread_; moved here for safety
transport_ = new PipelineTransport(this);
}
MediaPipeline::~MediaPipeline() {
ASSERT_ON_THREAD(main_thread_);
- MOZ_MTLOG(ML_INFO, "Destroying MediaPipeline: " << description_);
+ CSFLogInfo(LOGTAG, "Destroying MediaPipeline: %s", description_.c_str());
}
nsresult MediaPipeline::Init() {
ASSERT_ON_THREAD(main_thread_);
if (direction_ == RECEIVE) {
conduit_->SetReceiverTransport(transport_);
} else {
@@ -758,17 +764,17 @@ MediaPipeline::GetContributingSourceStat
}
}
void MediaPipeline::StateChange(TransportFlow *flow, TransportLayer::State state) {
TransportInfo* info = GetTransportInfo_s(flow);
MOZ_ASSERT(info);
if (state == TransportLayer::TS_OPEN) {
- MOZ_MTLOG(ML_INFO, "Flow is ready");
+ CSFLogInfo(LOGTAG, "Flow is ready");
TransportReady_s(*info);
} else if (state == TransportLayer::TS_CLOSED ||
state == TransportLayer::TS_ERROR) {
TransportFailed_s(*info);
}
}
static bool MakeRtpTypeToStringArray(const char** array) {
@@ -790,48 +796,47 @@ static const char* ToString(MediaPipelin
}
nsresult MediaPipeline::TransportReady_s(TransportInfo &info) {
MOZ_ASSERT(!description_.empty());
// TODO(ekr@rtfm.com): implement some kind of notification on
// failure. bug 852665.
if (info.state_ != MP_CONNECTING) {
- MOZ_MTLOG(ML_ERROR, "Transport ready for flow in wrong state:" <<
- description_ << ": " << ToString(info.type_));
+ CSFLogError(LOGTAG, "Transport ready for flow in wrong state:%s :%s",
+ description_.c_str(), ToString(info.type_));
return NS_ERROR_FAILURE;
}
- MOZ_MTLOG(ML_INFO, "Transport ready for pipeline " <<
- static_cast<void *>(this) << " flow " << description_ << ": " <<
- ToString(info.type_));
+ CSFLogInfo(LOGTAG, "Transport ready for pipeline %p flow %s: %s", this,
+ description_.c_str(), ToString(info.type_));
// TODO(bcampen@mozilla.com): Should we disconnect from the flow on failure?
nsresult res;
// Now instantiate the SRTP objects
TransportLayerDtls *dtls = static_cast<TransportLayerDtls *>(
info.transport_->GetLayer(TransportLayerDtls::ID()));
MOZ_ASSERT(dtls); // DTLS is mandatory
uint16_t cipher_suite;
res = dtls->GetSrtpCipher(&cipher_suite);
if (NS_FAILED(res)) {
- MOZ_MTLOG(ML_ERROR, "Failed to negotiate DTLS-SRTP. This is an error");
+ CSFLogError(LOGTAG, "Failed to negotiate DTLS-SRTP. This is an error");
info.state_ = MP_CLOSED;
UpdateRtcpMuxState(info);
return res;
}
// SRTP Key Exporter as per RFC 5764 S 4.2
unsigned char srtp_block[SRTP_TOTAL_KEY_LENGTH * 2];
res = dtls->ExportKeyingMaterial(kDTLSExporterLabel, false, "",
srtp_block, sizeof(srtp_block));
if (NS_FAILED(res)) {
- MOZ_MTLOG(ML_ERROR, "Failed to compute DTLS-SRTP keys. This is an error");
+ CSFLogError(LOGTAG, "Failed to compute DTLS-SRTP keys. This is an error");
info.state_ = MP_CLOSED;
UpdateRtcpMuxState(info);
MOZ_CRASH(); // TODO: Remove once we have enough field experience to
// know it doesn't happen. bug 798797. Note that the
// code after this never executes.
return res;
}
@@ -863,26 +868,25 @@ nsresult MediaPipeline::TransportReady_s
}
MOZ_ASSERT(!info.send_srtp_ && !info.recv_srtp_);
info.send_srtp_ = SrtpFlow::Create(cipher_suite, false, write_key,
SRTP_TOTAL_KEY_LENGTH);
info.recv_srtp_ = SrtpFlow::Create(cipher_suite, true, read_key,
SRTP_TOTAL_KEY_LENGTH);
if (!info.send_srtp_ || !info.recv_srtp_) {
- MOZ_MTLOG(ML_ERROR, "Couldn't create SRTP flow for "
- << ToString(info.type_));
+ CSFLogError(LOGTAG, "Couldn't create SRTP flow for %s",
+ ToString(info.type_));
info.state_ = MP_CLOSED;
UpdateRtcpMuxState(info);
return NS_ERROR_FAILURE;
}
- MOZ_MTLOG(ML_INFO, "Listening for " << ToString(info.type_)
- << " packets received on " <<
- static_cast<void *>(dtls->downward()));
+ CSFLogInfo(LOGTAG, "Listening for %s packets received on %p",
+ ToString(info.type_), dtls->downward());
switch (info.type_) {
case RTP:
dtls->downward()->SignalPacketReceived.connect(
this,
&MediaPipeline::RtpPacketReceived);
break;
case RTCP:
@@ -905,17 +909,17 @@ nsresult MediaPipeline::TransportReady_s
}
nsresult MediaPipeline::TransportFailed_s(TransportInfo &info) {
ASSERT_ON_THREAD(sts_thread_);
info.state_ = MP_CLOSED;
UpdateRtcpMuxState(info);
- MOZ_MTLOG(ML_INFO, "Transport closed for flow " << ToString(info.type_));
+ CSFLogInfo(LOGTAG, "Transport closed for flow %s", ToString(info.type_));
NS_WARNING(
"MediaPipeline Transport failed. This is not properly cleaned up yet");
// TODO(ekr@rtfm.com): SECURITY: Figure out how to clean up if the
// connection was good and now it is bad.
// TODO(ekr@rtfm.com): Report up so that the PC knows we
// have experienced an error.
@@ -947,88 +951,82 @@ nsresult MediaPipeline::SendPacket(Trans
TransportResult res = dtls->downward()->
SendPacket(static_cast<const unsigned char *>(data), len);
if (res != len) {
// Ignore blocking indications
if (res == TE_WOULDBLOCK)
return NS_OK;
- MOZ_MTLOG(ML_ERROR, "Failed write on stream " << description_);
+ CSFLogError(LOGTAG, "Failed write on stream %s", description_.c_str());
return NS_BASE_STREAM_CLOSED;
}
return NS_OK;
}
void MediaPipeline::increment_rtp_packets_sent(int32_t bytes) {
++rtp_packets_sent_;
rtp_bytes_sent_ += bytes;
if (!(rtp_packets_sent_ % 100)) {
- MOZ_MTLOG(ML_INFO, "RTP sent packet count for " << description_
- << " Pipeline " << static_cast<void *>(this)
- << " Flow : " << static_cast<void *>(rtp_.transport_)
- << ": " << rtp_packets_sent_
- << " (" << rtp_bytes_sent_ << " bytes)");
+ CSFLogInfo(LOGTAG, "RTP sent packet count for %s Pipeline %p Flow: %p: %u (%" PRId64 " bytes)",
+ description_.c_str(), this, static_cast<void *>(rtp_.transport_),
+ rtp_packets_sent_, rtp_bytes_sent_);
}
}
void MediaPipeline::increment_rtcp_packets_sent() {
++rtcp_packets_sent_;
if (!(rtcp_packets_sent_ % 100)) {
- MOZ_MTLOG(ML_INFO, "RTCP sent packet count for " << description_
- << " Pipeline " << static_cast<void *>(this)
- << " Flow : " << static_cast<void *>(rtcp_.transport_)
- << ": " << rtcp_packets_sent_);
+ CSFLogInfo(LOGTAG, "RTCP sent packet count for %s Pipeline %p Flow: %p: %u",
+ description_.c_str(), this, static_cast<void *>(rtp_.transport_),
+ rtcp_packets_sent_);
}
}
void MediaPipeline::increment_rtp_packets_received(int32_t bytes) {
++rtp_packets_received_;
rtp_bytes_received_ += bytes;
if (!(rtp_packets_received_ % 100)) {
- MOZ_MTLOG(ML_INFO, "RTP received packet count for " << description_
- << " Pipeline " << static_cast<void *>(this)
- << " Flow : " << static_cast<void *>(rtp_.transport_)
- << ": " << rtp_packets_received_
- << " (" << rtp_bytes_received_ << " bytes)");
+ CSFLogInfo(LOGTAG, "RTP received packet count for %s Pipeline %p Flow: %p: %u (%" PRId64 " bytes)",
+ description_.c_str(), this, static_cast<void *>(rtp_.transport_),
+ rtp_packets_received_, rtp_bytes_received_);
}
}
void MediaPipeline::increment_rtcp_packets_received() {
++rtcp_packets_received_;
if (!(rtcp_packets_received_ % 100)) {
- MOZ_MTLOG(ML_INFO, "RTCP received packet count for " << description_
- << " Pipeline " << static_cast<void *>(this)
- << " Flow : " << static_cast<void *>(rtcp_.transport_)
- << ": " << rtcp_packets_received_);
+ CSFLogInfo(LOGTAG, "RTCP received packet count for %s Pipeline %p Flow: %p: %u",
+ description_.c_str(), this, static_cast<void *>(rtp_.transport_),
+ rtcp_packets_received_);
}
}
void MediaPipeline::RtpPacketReceived(TransportLayer *layer,
const unsigned char *data,
size_t len) {
if (!transport_->pipeline()) {
- MOZ_MTLOG(ML_ERROR, "Discarding incoming packet; transport disconnected");
+ CSFLogError(LOGTAG, "Discarding incoming packet; transport disconnected");
return;
}
if (!conduit_) {
- MOZ_MTLOG(ML_DEBUG, "Discarding incoming packet; media disconnected");
+ CSFLogDebug(LOGTAG, "Discarding incoming packet; media disconnected");
return;
}
if (rtp_.state_ != MP_OPEN) {
- MOZ_MTLOG(ML_ERROR, "Discarding incoming packet; pipeline not open");
+ CSFLogError(LOGTAG, "Discarding incoming packet; pipeline not open");
return;
}
if (rtp_.transport_->state() != TransportLayer::TS_OPEN) {
- MOZ_MTLOG(ML_ERROR, "Discarding incoming packet; transport not open");
+ CSFLogError(LOGTAG, "Discarding incoming packet; transport not open");
return;
}
// This should never happen.
MOZ_ASSERT(rtp_.recv_srtp_);
if (direction_ == TRANSMIT) {
return;
@@ -1100,49 +1098,49 @@ void MediaPipeline::RtpPacketReceived(Tr
char tmp[16];
SprintfLiteral(tmp, "%.2x %.2x %.2x %.2x",
inner_data[0],
inner_data[1],
inner_data[2],
inner_data[3]);
- MOZ_MTLOG(ML_NOTICE, "Error unprotecting RTP in " << description_
- << "len= " << len << "[" << tmp << "...]");
+ CSFLogError(LOGTAG, "Error unprotecting RTP in %s len= %zu [%s]",
+ description_.c_str(), len, tmp);
return;
}
- MOZ_MTLOG(ML_DEBUG, description_ << " received RTP packet.");
+ CSFLogDebug(LOGTAG, "%s received RTP packet.", description_.c_str());
increment_rtp_packets_received(out_len);
RtpLogger::LogPacket(inner_data.get(), out_len, true, true, header.headerLength,
description_);
(void)conduit_->ReceivedRTPPacket(inner_data.get(), out_len, header.ssrc); // Ignore error codes
}
void MediaPipeline::RtcpPacketReceived(TransportLayer *layer,
const unsigned char *data,
size_t len) {
if (!transport_->pipeline()) {
- MOZ_MTLOG(ML_DEBUG, "Discarding incoming packet; transport disconnected");
+ CSFLogDebug(LOGTAG, "Discarding incoming packet; transport disconnected");
return;
}
if (!conduit_) {
- MOZ_MTLOG(ML_DEBUG, "Discarding incoming packet; media disconnected");
+ CSFLogDebug(LOGTAG, "Discarding incoming packet; media disconnected");
return;
}
if (rtcp_.state_ != MP_OPEN) {
- MOZ_MTLOG(ML_DEBUG, "Discarding incoming packet; pipeline not open");
+ CSFLogDebug(LOGTAG, "Discarding incoming packet; pipeline not open");
return;
}
if (rtcp_.transport_->state() != TransportLayer::TS_OPEN) {
- MOZ_MTLOG(ML_ERROR, "Discarding incoming packet; transport not open");
+ CSFLogError(LOGTAG, "Discarding incoming packet; transport not open");
return;
}
if (!len) {
return;
}
// Filter out everything but RTP/RTCP
@@ -1150,17 +1148,17 @@ void MediaPipeline::RtcpPacketReceived(T
return;
}
// We do not filter RTCP for send pipelines, since the webrtc.org code for
// senders already has logic to ignore RRs that do not apply.
// TODO bug 1279153: remove SR check for reduced size RTCP
if (filter_ && direction_ == RECEIVE) {
if (!filter_->FilterSenderReport(data, len)) {
- MOZ_MTLOG(ML_NOTICE, "Dropping incoming RTCP packet; filtered out");
+ CSFLogWarn(LOGTAG, "Dropping incoming RTCP packet; filtered out");
return;
}
}
// Make a copy rather than cast away constness
auto inner_data = MakeUnique<unsigned char[]>(len);
memcpy(inner_data.get(), data, len);
int out_len;
@@ -1168,17 +1166,17 @@ void MediaPipeline::RtcpPacketReceived(T
nsresult res = rtcp_.recv_srtp_->UnprotectRtcp(inner_data.get(),
len,
len,
&out_len);
if (!NS_SUCCEEDED(res))
return;
- MOZ_MTLOG(ML_DEBUG, description_ << " received RTCP packet.");
+ CSFLogDebug(LOGTAG, "%s received RTCP packet.", description_.c_str());
increment_rtcp_packets_received();
RtpLogger::LogPacket(inner_data.get(), out_len, true, false, 0, description_);
MOZ_ASSERT(rtcp_.recv_srtp_); // This should never happen
(void)conduit_->ReceivedRTCPPacket(inner_data.get(), out_len); // Ignore error codes
}
@@ -1215,17 +1213,17 @@ bool MediaPipeline::IsRtp(const unsigned
MOZ_ASSERT(false); // Not reached, belt and suspenders.
return true;
}
void MediaPipeline::PacketReceived(TransportLayer *layer,
const unsigned char *data,
size_t len) {
if (!transport_->pipeline()) {
- MOZ_MTLOG(ML_DEBUG, "Discarding incoming packet; transport disconnected");
+ CSFLogDebug(LOGTAG, "Discarding incoming packet; transport disconnected");
return;
}
if (IsRtp(data, len)) {
RtpPacketReceived(layer, data, len);
} else {
RtcpPacketReceived(layer, data, len);
}
@@ -1462,19 +1460,18 @@ void MediaPipelineTransmit::AttachToTrac
description_ = pc_ + "| ";
description_ += conduit_->type() == MediaSessionConduit::AUDIO ?
"Transmit audio[" : "Transmit video[";
description_ += track_id;
description_ += "]";
// TODO(ekr@rtfm.com): Check for errors
- MOZ_MTLOG(ML_DEBUG, "Attaching pipeline to track "
- << static_cast<void *>(domtrack_) << " conduit type=" <<
- (conduit_->type() == MediaSessionConduit::AUDIO ?"audio":"video"));
+ CSFLogDebug(LOGTAG, "Attaching pipeline to track %p conduit type=%s", this,
+ (conduit_->type() == MediaSessionConduit::AUDIO ?"audio":"video"));
#if !defined(MOZILLA_EXTERNAL_LINKAGE)
// With full duplex we don't risk having audio come in late to the MSG
// so we won't need a direct listener.
const bool enableDirectListener =
!Preferences::GetBool("media.navigator.audio.full_duplex", false);
#else
const bool enableDirectListener = true;
@@ -1560,20 +1557,19 @@ nsresult MediaPipelineTransmit::Transpor
return NS_OK;
}
nsresult MediaPipelineTransmit::ReplaceTrack(MediaStreamTrack& domtrack) {
// MainThread, checked in calls we make
nsString nsTrackId;
domtrack.GetId(nsTrackId);
std::string track_id(NS_ConvertUTF16toUTF8(nsTrackId).get());
- MOZ_MTLOG(ML_DEBUG, "Reattaching pipeline " << description_ << " to track "
- << static_cast<void *>(&domtrack)
- << " track " << track_id << " conduit type=" <<
- (conduit_->type() == MediaSessionConduit::AUDIO ?"audio":"video"));
+ CSFLogDebug(LOGTAG, "Reattaching pipeline %s to track %p track %s conduit type: %s",
+ description_.c_str(), &domtrack, track_id.c_str(),
+ (conduit_->type() == MediaSessionConduit::AUDIO ?"audio":"video"));
DetachMedia();
domtrack_ = &domtrack; // Detach clears it
// Unsets the track id after RemoveListener() takes effect.
listener_->UnsetTrackId(domtrack_->GraphImpl());
track_id_ = track_id;
AttachToTrack(track_id);
return NS_OK;
@@ -1596,23 +1592,23 @@ void MediaPipeline::DisconnectTransport_
nsresult MediaPipeline::ConnectTransport_s(TransportInfo &info) {
MOZ_ASSERT(info.transport_);
ASSERT_ON_THREAD(sts_thread_);
// Look to see if the transport is ready
if (info.transport_->state() == TransportLayer::TS_OPEN) {
nsresult res = TransportReady_s(info);
if (NS_FAILED(res)) {
- MOZ_MTLOG(ML_ERROR, "Error calling TransportReady(); res="
- << static_cast<uint32_t>(res) << " in " << __FUNCTION__);
+ CSFLogError(LOGTAG, "Error calling TransportReady(); res=%u in %s",
+ static_cast<uint32_t>(res), __FUNCTION__);
return res;
}
} else if (info.transport_->state() == TransportLayer::TS_ERROR) {
- MOZ_MTLOG(ML_ERROR, ToString(info.type_)
- << "transport is already in error state");
+ CSFLogError(LOGTAG, "%s transport is already in error state",
+ ToString(info.type_));
TransportFailed_s(info);
return NS_ERROR_FAILURE;
}
info.transport_->SignalStateChange.connect(this,
&MediaPipeline::StateChange);
return NS_OK;
@@ -1653,17 +1649,17 @@ nsresult MediaPipeline::PipelineTranspor
ASSERT_ON_THREAD(sts_thread_);
if (!pipeline_) {
return NS_OK; // Detached
}
TransportInfo& transport = is_rtp ? pipeline_->rtp_ : pipeline_->rtcp_;
if (!transport.send_srtp_) {
- MOZ_MTLOG(ML_DEBUG, "Couldn't write RTP/RTCP packet; SRTP not set up yet");
+ CSFLogDebug(LOGTAG, "Couldn't write RTP/RTCP packet; SRTP not set up yet");
return NS_OK;
}
MOZ_ASSERT(transport.transport_);
NS_ENSURE_TRUE(transport.transport_, NS_ERROR_NULL_POINTER);
// libsrtp enciphers in place, so we need a big enough buffer.
MOZ_ASSERT(data->capacity() >= data->len() + SRTP_MAX_EXPANSION);
@@ -1694,18 +1690,18 @@ nsresult MediaPipeline::PipelineTranspor
}
if (!NS_SUCCEEDED(res)) {
return res;
}
// paranoia; don't have uninitialized bytes included in data->len()
data->SetLength(out_len);
- MOZ_MTLOG(ML_DEBUG, pipeline_->description_ << " sending " <<
- (is_rtp ? "RTP" : "RTCP") << " packet");
+ CSFLogDebug(LOGTAG, "%s sending %s packet", pipeline_->description_.c_str(),
+ (is_rtp ? "RTP" : "RTCP"));
if (is_rtp) {
pipeline_->increment_rtp_packets_sent(out_len);
} else {
pipeline_->increment_rtcp_packets_sent();
}
return pipeline_->SendPacket(transport.transport_, data->data(), out_len);
}
@@ -1738,35 +1734,34 @@ UnsetTrackId(MediaStreamGraphImpl* graph
};
graph->AppendMessage(MakeUnique<Message>(this));
}
// Called if we're attached with AddDirectListener()
void MediaPipelineTransmit::PipelineListener::
NotifyRealtimeTrackData(MediaStreamGraph* graph,
StreamTime offset,
const MediaSegment& media) {
- MOZ_MTLOG(ML_DEBUG, "MediaPipeline::NotifyRealtimeTrackData() listener=" <<
- this << ", offset=" << offset <<
- ", duration=" << media.GetDuration());
+ CSFLogDebug(LOGTAG, "MediaPipeline::NotifyRealtimeTrackData() listener=%p, offset=%" PRId64 ", duration=%" PRId64,
+ this, offset, media.GetDuration());
if (media.GetType() == MediaSegment::VIDEO) {
// We have to call the upstream NotifyRealtimeTrackData and
// MediaStreamVideoSink will route them to SetCurrentFrames.
MediaStreamVideoSink::NotifyRealtimeTrackData(graph, offset, media);
return;
}
NewData(media, graph->GraphRate());
}
void MediaPipelineTransmit::PipelineListener::
NotifyQueuedChanges(MediaStreamGraph* graph,
StreamTime offset,
const MediaSegment& queued_media) {
- MOZ_MTLOG(ML_DEBUG, "MediaPipeline::NotifyQueuedChanges()");
+ CSFLogDebug(LOGTAG, "MediaPipeline::NotifyQueuedChanges()");
if (queued_media.GetType() == MediaSegment::VIDEO) {
// We always get video from SetCurrentFrames().
return;
}
if (direct_connect_) {
// ignore non-direct data if we're also getting direct data
@@ -1780,33 +1775,33 @@ NotifyQueuedChanges(MediaStreamGraph* gr
// When running tests, graph may be null. In that case use a default.
rate = 16000;
}
NewData(queued_media, rate);
}
void MediaPipelineTransmit::PipelineListener::
NotifyDirectListenerInstalled(InstallationResult aResult) {
- MOZ_MTLOG(ML_INFO, "MediaPipeline::NotifyDirectListenerInstalled() listener= " <<
- this << ", result=" << static_cast<int32_t>(aResult));
+ CSFLogInfo(LOGTAG, "MediaPipeline::NotifyDirectListenerInstalled() listener=%p, result=%d",
+ this, static_cast<int32_t>(aResult));
direct_connect_ = InstallationResult::SUCCESS == aResult;
}
void MediaPipelineTransmit::PipelineListener::
NotifyDirectListenerUninstalled() {
- MOZ_MTLOG(ML_INFO, "MediaPipeline::NotifyDirectListenerUninstalled() listener=" << this);
+ CSFLogInfo(LOGTAG, "MediaPipeline::NotifyDirectListenerUninstalled() listener=%p", this);
direct_connect_ = false;
}
void MediaPipelineTransmit::PipelineListener::
NewData(const MediaSegment& media, TrackRate aRate /* = 0 */) {
if (!active_) {
- MOZ_MTLOG(ML_DEBUG, "Discarding packets because transport not ready");
+ CSFLogDebug(LOGTAG, "Discarding packets because transport not ready");
return;
}
if (conduit_->type() !=
(media.GetType() == MediaSegment::AUDIO ? MediaSessionConduit::AUDIO :
MediaSessionConduit::VIDEO)) {
MOZ_ASSERT(false, "The media type should always be correct since the "
"listener is locked to a specific track");
@@ -1996,17 +1991,17 @@ public:
}
}
// Implement MediaStreamListener
void NotifyPull(MediaStreamGraph* graph, StreamTime desired_time) override
{
MOZ_ASSERT(source_);
if (!source_) {
- MOZ_MTLOG(ML_ERROR, "NotifyPull() called from a non-SourceMediaStream");
+ CSFLogError(LOGTAG, "NotifyPull() called from a non-SourceMediaStream");
return;
}
// This comparison is done in total time to avoid accumulated roundoff errors.
while (source_->TicksToTimeRoundDown(WEBRTC_DEFAULT_SAMPLE_RATE,
played_ticks_) < desired_time) {
int16_t scratch_buffer[AUDIO_SAMPLE_BUFFER_MAX_BYTES / sizeof(int16_t)];
@@ -2017,29 +2012,28 @@ public:
static_cast<AudioSessionConduit*>(conduit_.get())->GetAudioFrame(
scratch_buffer,
WEBRTC_DEFAULT_SAMPLE_RATE,
0, // TODO(ekr@rtfm.com): better estimate of "capture" (really playout) delay
samples_length);
if (err != kMediaConduitNoError) {
// Insert silence on conduit/GIPS failure (extremely unlikely)
- MOZ_MTLOG(ML_ERROR, "Audio conduit failed (" << err
- << ") to return data @ " << played_ticks_
- << " (desired " << desired_time << " -> "
- << source_->StreamTimeToSeconds(desired_time) << ")");
+ CSFLogError(LOGTAG, "Audio conduit failed (%d) to return data @ %" PRId64 " (desired %" PRId64 " -> %f)",
+ err, played_ticks_, desired_time,
+ source_->StreamTimeToSeconds(desired_time));
// if this is not enough we'll loop and provide more
samples_length = WEBRTC_DEFAULT_SAMPLE_RATE/100;
PodArrayZero(scratch_buffer);
}
MOZ_ASSERT(samples_length * sizeof(uint16_t) < AUDIO_SAMPLE_BUFFER_MAX_BYTES);
- MOZ_MTLOG(ML_DEBUG, "Audio conduit returned buffer of length "
- << samples_length);
+ CSFLogDebug(LOGTAG, "Audio conduit returned buffer of length %u",
+ samples_length);
RefPtr<SharedBuffer> samples = SharedBuffer::Create(samples_length * sizeof(uint16_t));
int16_t *samples_data = static_cast<int16_t *>(samples->Data());
AudioSegment segment;
// We derive the number of channels of the stream from the number of samples
// the AudioConduit gives us, considering it gives us packets of 10ms and we
// know the rate.
uint32_t channelCount = samples_length / (WEBRTC_DEFAULT_SAMPLE_RATE / 100);
@@ -2072,17 +2066,17 @@ public:
if (played_ticks_ > last_log_ + WEBRTC_DEFAULT_SAMPLE_RATE) { // ~ 1 second
MOZ_LOG(AudioLogModule(), LogLevel::Debug,
("%p: Inserting %zu samples into track %d, total = %" PRIu64,
(void*) this, frames, track_id_, played_ticks_));
last_log_ = played_ticks_;
}
}
} else {
- MOZ_MTLOG(ML_ERROR, "AppendToTrack failed");
+ CSFLogError(LOGTAG, "AppendToTrack failed");
// we can't un-read the data, but that's ok since we don't want to
// buffer - but don't i-loop!
return;
}
}
}
private:
@@ -2118,17 +2112,17 @@ void MediaPipelineReceiveAudio::DetachMe
}
stream_ = nullptr;
}
}
nsresult MediaPipelineReceiveAudio::Init()
{
ASSERT_ON_THREAD(main_thread_);
- MOZ_MTLOG(ML_DEBUG, __FUNCTION__);
+ CSFLogDebug(LOGTAG, "%s", __FUNCTION__);
description_ = pc_ + "| Receive audio[";
description_ += track_id_;
description_ += "]";
listener_->AddSelf();
return MediaPipelineReceive::Init();
@@ -2166,17 +2160,17 @@ public:
if (delta > 0) {
VideoSegment segment;
IntSize size = image ? image->GetSize() : IntSize(width_, height_);
segment.AppendFrame(image.forget(), delta, size, principal_handle_);
// Handle track not actually added yet or removed/finished
if (source_->AppendToTrack(track_id_, &segment)) {
played_ticks_ = desired_time;
} else {
- MOZ_MTLOG(ML_ERROR, "AppendToTrack failed");
+ CSFLogError(LOGTAG, "AppendToTrack failed");
return;
}
}
}
// Accessors for external writes from the renderer
void FrameSizeChange(unsigned int width,
unsigned int height,
@@ -2300,17 +2294,17 @@ void MediaPipelineReceiveVideo::DetachMe
listener_->EndTrack();
stream_->RemoveListener(listener_);
stream_ = nullptr;
}
}
nsresult MediaPipelineReceiveVideo::Init() {
ASSERT_ON_THREAD(main_thread_);
- MOZ_MTLOG(ML_DEBUG, __FUNCTION__);
+ CSFLogDebug(LOGTAG, "%s", __FUNCTION__);
description_ = pc_ + "| Receive video[";
description_ += track_id_;
description_ += "]";
listener_->AddSelf();
// Always happens before we can DetachMedia()
--- a/media/webrtc/signaling/src/mediapipeline/SrtpFlow.cpp
+++ b/media/webrtc/signaling/src/mediapipeline/SrtpFlow.cpp
@@ -8,19 +8,23 @@
#include "SrtpFlow.h"
#include "srtp.h"
#include "ssl.h"
#include "sslproto.h"
#include "mozilla/RefPtr.h"
-// Logging context
+static const char* sfLogTag = "SrtpFlow";
+#ifdef LOGTAG
+#undef LOGTAG
+#endif
+#define LOGTAG sfLogTag
+
using namespace mozilla;
-MOZ_MTLOG_MODULE("mediapipeline")
namespace mozilla {
bool SrtpFlow::initialized; // Static
SrtpFlow::~SrtpFlow() {
if (session_) {
srtp_dealloc(session_);
@@ -33,97 +37,97 @@ RefPtr<SrtpFlow> SrtpFlow::Create(int ci
size_t key_len) {
nsresult res = Init();
if (!NS_SUCCEEDED(res))
return nullptr;
RefPtr<SrtpFlow> flow = new SrtpFlow();
if (!key) {
- MOZ_MTLOG(ML_ERROR, "Null SRTP key specified");
+ CSFLogError(LOGTAG, "Null SRTP key specified");
return nullptr;
}
if (key_len != SRTP_TOTAL_KEY_LENGTH) {
- MOZ_MTLOG(ML_ERROR, "Invalid SRTP key length");
+ CSFLogError(LOGTAG, "Invalid SRTP key length");
return nullptr;
}
srtp_policy_t policy;
memset(&policy, 0, sizeof(srtp_policy_t));
// Note that we set the same cipher suite for RTP and RTCP
// since any flow can only have one cipher suite with DTLS-SRTP
switch (cipher_suite) {
case SRTP_AES128_CM_HMAC_SHA1_80:
- MOZ_MTLOG(ML_DEBUG,
- "Setting SRTP cipher suite SRTP_AES128_CM_HMAC_SHA1_80");
+ CSFLogDebug(LOGTAG,
+ "Setting SRTP cipher suite SRTP_AES128_CM_HMAC_SHA1_80");
crypto_policy_set_aes_cm_128_hmac_sha1_80(&policy.rtp);
crypto_policy_set_aes_cm_128_hmac_sha1_80(&policy.rtcp);
break;
case SRTP_AES128_CM_HMAC_SHA1_32:
- MOZ_MTLOG(ML_DEBUG,
- "Setting SRTP cipher suite SRTP_AES128_CM_HMAC_SHA1_32");
+ CSFLogDebug(LOGTAG,
+ "Setting SRTP cipher suite SRTP_AES128_CM_HMAC_SHA1_32");
crypto_policy_set_aes_cm_128_hmac_sha1_32(&policy.rtp);
crypto_policy_set_aes_cm_128_hmac_sha1_80(&policy.rtcp); // 80-bit per RFC 5764
break; // S 4.1.2.
default:
- MOZ_MTLOG(ML_ERROR, "Request to set unknown SRTP cipher suite");
+ CSFLogError(LOGTAG, "Request to set unknown SRTP cipher suite");
return nullptr;
}
// This key is copied into the srtp_t object, so we don't
// need to keep it.
policy.key = const_cast<unsigned char *>(
static_cast<const unsigned char *>(key));
policy.ssrc.type = inbound ? ssrc_any_inbound : ssrc_any_outbound;
policy.ssrc.value = 0;
policy.ekt = nullptr;
policy.window_size = 1024; // Use the Chrome value. Needs to be revisited. Default is 128
policy.allow_repeat_tx = 1; // Use Chrome value; needed for NACK mode to work
policy.next = nullptr;
// Now make the session
err_status_t r = srtp_create(&flow->session_, &policy);
if (r != err_status_ok) {
- MOZ_MTLOG(ML_ERROR, "Error creating srtp session");
+ CSFLogError(LOGTAG, "Error creating srtp session");
return nullptr;
}
return flow;
}
nsresult SrtpFlow::CheckInputs(bool protect, void *in, int in_len,
int max_len, int *out_len) {
MOZ_ASSERT(in);
if (!in) {
- MOZ_MTLOG(ML_ERROR, "NULL input value");
+ CSFLogError(LOGTAG, "NULL input value");
return NS_ERROR_NULL_POINTER;
}
if (in_len < 0) {
- MOZ_MTLOG(ML_ERROR, "Input length is negative");
+ CSFLogError(LOGTAG, "Input length is negative");
return NS_ERROR_ILLEGAL_VALUE;
}
if (max_len < 0) {
- MOZ_MTLOG(ML_ERROR, "Max output length is negative");
+ CSFLogError(LOGTAG, "Max output length is negative");
return NS_ERROR_ILLEGAL_VALUE;
}
if (protect) {
if ((max_len < SRTP_MAX_EXPANSION) ||
((max_len - SRTP_MAX_EXPANSION) < in_len)) {
- MOZ_MTLOG(ML_ERROR, "Output too short");
+ CSFLogError(LOGTAG, "Output too short");
return NS_ERROR_ILLEGAL_VALUE;
}
}
else {
if (in_len > max_len) {
- MOZ_MTLOG(ML_ERROR, "Output too short");
+ CSFLogError(LOGTAG, "Output too short");
return NS_ERROR_ILLEGAL_VALUE;
}
}
return NS_OK;
}
nsresult SrtpFlow::ProtectRtp(void *in, int in_len,
@@ -131,117 +135,117 @@ nsresult SrtpFlow::ProtectRtp(void *in,
nsresult res = CheckInputs(true, in, in_len, max_len, out_len);
if (NS_FAILED(res))
return res;
int len = in_len;
err_status_t r = srtp_protect(session_, in, &len);
if (r != err_status_ok) {
- MOZ_MTLOG(ML_ERROR, "Error protecting SRTP packet");
+ CSFLogError(LOGTAG, "Error protecting SRTP packet");
return NS_ERROR_FAILURE;
}
MOZ_ASSERT(len <= max_len);
*out_len = len;
- MOZ_MTLOG(ML_DEBUG, "Successfully protected an SRTP packet of len "
- << *out_len);
+ CSFLogDebug(LOGTAG, "Successfully protected an SRTP packet of len %d",
+ *out_len);
return NS_OK;
}
nsresult SrtpFlow::UnprotectRtp(void *in, int in_len,
int max_len, int *out_len) {
nsresult res = CheckInputs(false, in, in_len, max_len, out_len);
if (NS_FAILED(res))
return res;
int len = in_len;
err_status_t r = srtp_unprotect(session_, in, &len);
if (r != err_status_ok) {
- MOZ_MTLOG(ML_ERROR, "Error unprotecting SRTP packet error=" << (int)r);
+ CSFLogError(LOGTAG, "Error unprotecting SRTP packet error=%d", (int)r);
return NS_ERROR_FAILURE;
}
MOZ_ASSERT(len <= max_len);
*out_len = len;
- MOZ_MTLOG(ML_DEBUG, "Successfully unprotected an SRTP packet of len "
- << *out_len);
+ CSFLogDebug(LOGTAG, "Successfully unprotected an SRTP packet of len %d",
+ *out_len);
return NS_OK;
}
nsresult SrtpFlow::ProtectRtcp(void *in, int in_len,
int max_len, int *out_len) {
nsresult res = CheckInputs(true, in, in_len, max_len, out_len);
if (NS_FAILED(res))
return res;
int len = in_len;
err_status_t r = srtp_protect_rtcp(session_, in, &len);
if (r != err_status_ok) {
- MOZ_MTLOG(ML_ERROR, "Error protecting SRTCP packet");
+ CSFLogError(LOGTAG, "Error protecting SRTCP packet");
return NS_ERROR_FAILURE;
}
MOZ_ASSERT(len <= max_len);
*out_len = len;
- MOZ_MTLOG(ML_DEBUG, "Successfully protected an SRTCP packet of len "
- << *out_len);
+ CSFLogDebug(LOGTAG, "Successfully protected an SRTCP packet of len %d",
+ *out_len);
return NS_OK;
}
nsresult SrtpFlow::UnprotectRtcp(void *in, int in_len,
int max_len, int *out_len) {
nsresult res = CheckInputs(false, in, in_len, max_len, out_len);
if (NS_FAILED(res))
return res;
int len = in_len;
err_status_t r = srtp_unprotect_rtcp(session_, in, &len);
if (r != err_status_ok) {
- MOZ_MTLOG(ML_ERROR, "Error unprotecting SRTCP packet error=" << (int)r);
+ CSFLogError(LOGTAG, "Error unprotecting SRTCP packet error=%d", (int)r);
return NS_ERROR_FAILURE;
}
MOZ_ASSERT(len <= max_len);
*out_len = len;
- MOZ_MTLOG(ML_DEBUG, "Successfully unprotected an SRTCP packet of len "
- << *out_len);
+ CSFLogDebug(LOGTAG, "Successfully unprotected an SRTCP packet of len %d",
+ *out_len);
return NS_OK;
}
// Statics
void SrtpFlow::srtp_event_handler(srtp_event_data_t *data) {
// TODO(ekr@rtfm.com): Implement this
MOZ_CRASH();
}
nsresult SrtpFlow::Init() {
if (!initialized) {
err_status_t r = srtp_init();
if (r != err_status_ok) {
- MOZ_MTLOG(ML_ERROR, "Could not initialize SRTP");
+ CSFLogError(LOGTAG, "Could not initialize SRTP");
MOZ_ASSERT(PR_FALSE);
return NS_ERROR_FAILURE;
}
r = srtp_install_event_handler(&SrtpFlow::srtp_event_handler);
if (r != err_status_ok) {
- MOZ_MTLOG(ML_ERROR, "Could not install SRTP event handler");
+ CSFLogError(LOGTAG, "Could not install SRTP event handler");
MOZ_ASSERT(PR_FALSE);
return NS_ERROR_FAILURE;
}
initialized = true;
}
return NS_OK;