Bug 930481: Improved failure instrumentation for transport layers r=ekr
authorAdam Roach [:abr] <adam@nostrum.com>
Thu, 23 Jan 2014 14:21:24 -0600
changeset 164891 52b8d17dac75c2ddb94ca7eebad243e1ace2ea21
parent 164890 fbb3ea68c86e34e02f2e6b75b0f0f1cada0a07fd
child 164892 4219e97fcb8894838d60a68af68dc5d69ca92579
push id38852
push useradam@nostrum.com
push dateThu, 23 Jan 2014 20:21:34 +0000
treeherdermozilla-inbound@52b8d17dac75 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersekr
bugs930481
milestone29.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 930481: Improved failure instrumentation for transport layers r=ekr
media/mtransport/test/transport_unittests.cpp
media/mtransport/transportlayer.cpp
media/mtransport/transportlayer.h
media/mtransport/transportlayerdtls.cpp
media/mtransport/transportlayerice.cpp
media/mtransport/transportlayerlog.cpp
media/mtransport/transportlayerloopback.cpp
media/mtransport/transportlayerprsock.cpp
media/mtransport/transportlayerprsock.h
--- a/media/mtransport/test/transport_unittests.cpp
+++ b/media/mtransport/test/transport_unittests.cpp
@@ -91,17 +91,17 @@ class TransportLayerLossy : public Trans
     return downward_->SendPacket(data, len);
   }
 
   void SetLoss(uint32_t packet) {
     loss_mask_ |= (1 << (packet & 32));
   }
 
   void StateChange(TransportLayer *layer, State state) {
-    SetState(state);
+    TL_SET_STATE(state);
   }
 
   void PacketReceived(TransportLayer *layer, const unsigned char *data,
                       size_t len) {
     SignalPacketReceived(this, data, len);
   }
 
   TRANSPORT_LAYER_ID("lossy")
@@ -110,17 +110,17 @@ class TransportLayerLossy : public Trans
   virtual void WasInserted() {
     downward_->SignalPacketReceived.
         connect(this,
                 &TransportLayerLossy::PacketReceived);
     downward_->SignalStateChange.
         connect(this,
                 &TransportLayerLossy::StateChange);
 
-    SetState(downward_->state());
+    TL_SET_STATE(downward_->state());
   }
 
  private:
   uint32_t loss_mask_;
   uint32_t packet_;
 };
 
 namespace {
--- a/media/mtransport/transportlayer.cpp
+++ b/media/mtransport/transportlayer.cpp
@@ -34,19 +34,21 @@ void TransportLayer::Inserted(TransportF
   downward_ = downward;
   flow_id_ = flow->id();
   MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Inserted: downward='" <<
     (downward ? downward->id(): "none") << "'");
 
   WasInserted();
 }
 
-void TransportLayer::SetState(State state) {
+void TransportLayer::SetState(State state, const char *file, unsigned line) {
   if (state != state_) {
-    MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "state " << state_ << "->" << state);
+    MOZ_MTLOG(state == TS_ERROR ? ML_ERROR : ML_DEBUG,
+              file << ":" << line << ": " <<
+              LAYER_INFO << "state " << state_ << "->" << state);
     state_ = state;
     SignalStateChange(this, state);
   }
 }
 
 nsresult TransportLayer::RunOnThread(nsIRunnable *event) {
   if (target_) {
     nsIThread *thr;
--- a/media/mtransport/transportlayer.h
+++ b/media/mtransport/transportlayer.h
@@ -85,17 +85,17 @@ class TransportLayer : public sigslot::h
 
   // The id of the flow
   const std::string& flow_id() {
     return flow_id_;
   }
 
  protected:
   virtual void WasInserted() {}
-  virtual void SetState(State state);
+  virtual void SetState(State state, const char *file, unsigned line);
   // Check if we are on the right thread
   void CheckThread() {
     NS_ABORT_IF_FALSE(CheckThreadInt(), "Wrong thread");
   }
 
   Mode mode_;
   State state_;
   std::string flow_id_;
@@ -114,11 +114,12 @@ class TransportLayer : public sigslot::h
     NS_ENSURE_SUCCESS(target_->IsOnCurrentThread(&on), false);
     NS_ENSURE_TRUE(on, false);
 
     return true;
   }
 };
 
 #define LAYER_INFO "Flow[" << flow_id() << "(none)" << "]; Layer[" << id() << "]: "
+#define TL_SET_STATE(x) SetState((x), __FILE__, __LINE__)
 
 }  // close namespace
 #endif
--- a/media/mtransport/transportlayerdtls.cpp
+++ b/media/mtransport/transportlayerdtls.cpp
@@ -373,17 +373,17 @@ nsresult TransportLayerDtls::InitInterna
 
   return NS_OK;
 }
 
 
 void TransportLayerDtls::WasInserted() {
   // Connect to the lower layers
   if (!Setup()) {
-    SetState(TS_ERROR);
+    TL_SET_STATE(TS_ERROR);
   }
 }
 
 
 nsresult TransportLayerDtls::SetVerificationAllowAll() {
   // Defensive programming
   if (verification_mode_ != VERIFY_UNSET)
     return NS_ERROR_ALREADY_INITIALIZED;
@@ -585,77 +585,77 @@ bool TransportLayerDtls::Setup() {
 
   return true;
 }
 
 
 void TransportLayerDtls::StateChange(TransportLayer *layer, State state) {
   if (state <= state_) {
     MOZ_MTLOG(ML_ERROR, "Lower layer state is going backwards from ours");
-    SetState(TS_ERROR);
+    TL_SET_STATE(TS_ERROR);
     return;
   }
 
   switch (state) {
     case TS_NONE:
       MOZ_ASSERT(false);  // Can't happen
       break;
 
     case TS_INIT:
       MOZ_MTLOG(ML_ERROR,
                 LAYER_INFO << "State change of lower layer to INIT forbidden");
-      SetState(TS_ERROR);
+      TL_SET_STATE(TS_ERROR);
       break;
 
     case TS_CONNECTING:
       MOZ_MTLOG(ML_ERROR, LAYER_INFO << "Lower lower is connecting.");
       break;
 
     case TS_OPEN:
       MOZ_MTLOG(ML_ERROR,
                 LAYER_INFO << "Lower lower is now open; starting TLS");
       Handshake();
       break;
 
     case TS_CLOSED:
       MOZ_MTLOG(ML_ERROR, LAYER_INFO << "Lower lower is now closed");
-      SetState(TS_CLOSED);
+      TL_SET_STATE(TS_CLOSED);
       break;
 
     case TS_ERROR:
       MOZ_MTLOG(ML_ERROR, LAYER_INFO << "Lower lower experienced an error");
-      SetState(TS_ERROR);
+      TL_SET_STATE(TS_ERROR);
       break;
   }
 }
 
 void TransportLayerDtls::Handshake() {
-  SetState(TS_CONNECTING);
+  TL_SET_STATE(TS_CONNECTING);
 
   // Clear the retransmit timer
   timer_->Cancel();
 
   SECStatus rv = SSL_ForceHandshake(ssl_fd_);
 
   if (rv == SECSuccess) {
     MOZ_MTLOG(ML_NOTICE,
               LAYER_INFO << "****** SSL handshake completed ******");
     if (!cert_ok_) {
       MOZ_MTLOG(ML_ERROR, LAYER_INFO << "Certificate check never occurred");
-      SetState(TS_ERROR);
+      TL_SET_STATE(TS_ERROR);
       return;
     }
-    SetState(TS_OPEN);
+    TL_SET_STATE(TS_OPEN);
   } else {
     int32_t err = PR_GetError();
     switch(err) {
       case SSL_ERROR_RX_MALFORMED_HANDSHAKE:
         if (mode_ != DGRAM) {
           MOZ_MTLOG(ML_ERROR, LAYER_INFO << "Malformed TLS message");
-          SetState(TS_ERROR);
+          TL_SET_STATE(TS_ERROR);
         } else {
           MOZ_MTLOG(ML_ERROR, LAYER_INFO << "Malformed DTLS message; ignoring");
         }
         // Fall through
       case PR_WOULD_BLOCK_ERROR:
         MOZ_MTLOG(ML_NOTICE, LAYER_INFO << "Would have blocked");
         if (mode_ == DGRAM) {
           PRIntervalTime timeout;
@@ -669,17 +669,17 @@ void TransportLayerDtls::Handshake() {
             timer_->InitWithFuncCallback(TimerCallback,
                                          this, timeout_ms,
                                          nsITimer::TYPE_ONE_SHOT);
           }
         }
         break;
       default:
         MOZ_MTLOG(ML_ERROR, LAYER_INFO << "SSL handshake error "<< err);
-        SetState(TS_ERROR);
+        TL_SET_STATE(TS_ERROR);
         break;
     }
   }
 }
 
 void TransportLayerDtls::PacketReceived(TransportLayer* layer,
                                         const unsigned char *data,
                                         size_t len) {
@@ -704,26 +704,26 @@ void TransportLayerDtls::PacketReceived(
     unsigned char buf[2000];
 
     int32_t rv = PR_Recv(ssl_fd_, buf, sizeof(buf), 0, PR_INTERVAL_NO_WAIT);
     if (rv > 0) {
       // We have data
       MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Read " << rv << " bytes from NSS");
       SignalPacketReceived(this, buf, rv);
     } else if (rv == 0) {
-      SetState(TS_CLOSED);
+      TL_SET_STATE(TS_CLOSED);
     } else {
       int32_t err = PR_GetError();
 
       if (err == PR_WOULD_BLOCK_ERROR) {
         // This gets ignored
         MOZ_MTLOG(ML_NOTICE, LAYER_INFO << "Would have blocked");
       } else {
         MOZ_MTLOG(ML_NOTICE, LAYER_INFO << "NSS Error " << err);
-        SetState(TS_ERROR);
+        TL_SET_STATE(TS_ERROR);
       }
     }
   }
 }
 
 TransportResult TransportLayerDtls::SendPacket(const unsigned char *data,
                                                size_t len) {
   CheckThread();
@@ -737,30 +737,30 @@ TransportResult TransportLayerDtls::Send
 
   if (rv > 0) {
     // We have data
     MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Wrote " << rv << " bytes to SSL Layer");
     return rv;
   }
 
   if (rv == 0) {
-    SetState(TS_CLOSED);
+    TL_SET_STATE(TS_CLOSED);
     return 0;
   }
 
   int32_t err = PR_GetError();
 
   if (err == PR_WOULD_BLOCK_ERROR) {
     // This gets ignored
     MOZ_MTLOG(ML_NOTICE, LAYER_INFO << "Would have blocked");
     return TE_WOULDBLOCK;
   }
 
   MOZ_MTLOG(ML_NOTICE, LAYER_INFO << "NSS Error " << err);
-  SetState(TS_ERROR);
+  TL_SET_STATE(TS_ERROR);
   return TE_ERROR;
 }
 
 SECStatus TransportLayerDtls::GetClientAuthDataHook(void *arg, PRFileDesc *fd,
                                                     CERTDistNames *caNames,
                                                     CERTCertificate **pRetCert,
                                                     SECKEYPrivateKey **pRetKey) {
   MOZ_MTLOG(ML_DEBUG, "Server requested client auth");
--- a/media/mtransport/transportlayerice.cpp
+++ b/media/mtransport/transportlayerice.cpp
@@ -90,17 +90,17 @@ TransportLayerIce::TransportLayerIce(con
     : name_(name), ctx_(ctx), stream_(stream), component_(component) {
   target_ = ctx->thread();
 
   stream_->SignalReady.connect(this, &TransportLayerIce::IceReady);
   stream_->SignalFailed.connect(this, &TransportLayerIce::IceFailed);
   stream_->SignalPacketReceived.connect(this,
                                         &TransportLayerIce::IcePacketReceived);
   if (stream_->state() == NrIceMediaStream::ICE_OPEN) {
-    SetState(TS_OPEN);
+    TL_SET_STATE(TS_OPEN);
   }
 }
 
 TransportLayerIce::~TransportLayerIce() {
   // No need to do anything here, since we use smart pointers
 }
 
 TransportResult TransportLayerIce::SendPacket(const unsigned char *data,
@@ -121,22 +121,22 @@ TransportResult TransportLayerIce::SendP
 
 void TransportLayerIce::IceCandidate(NrIceMediaStream *stream,
                                      const std::string&) {
   // NO-OP for now
 }
 
 void TransportLayerIce::IceReady(NrIceMediaStream *stream) {
   CheckThread();
-  SetState(TS_OPEN);
+  TL_SET_STATE(TS_OPEN);
 }
 
 void TransportLayerIce::IceFailed(NrIceMediaStream *stream) {
   CheckThread();
-  SetState(TS_ERROR);
+  TL_SET_STATE(TS_ERROR);
 }
 
 void TransportLayerIce::IcePacketReceived(NrIceMediaStream *stream, int component,
                        const unsigned char *data, int len) {
   CheckThread();
   // We get packets for both components, so ignore the ones that aren't
   // for us.
   if (component_ != component)
--- a/media/mtransport/transportlayerlog.cpp
+++ b/media/mtransport/transportlayerlog.cpp
@@ -15,17 +15,17 @@ namespace mozilla {
 MOZ_MTLOG_MODULE("mtransport")
 
 void TransportLayerLogging::WasInserted() {
   if (downward_) {
     downward_->SignalStateChange.connect(
         this, &TransportLayerLogging::StateChange);
     downward_->SignalPacketReceived.connect(
         this, &TransportLayerLogging::PacketReceived);
-    SetState(downward_->state());
+    TL_SET_STATE(downward_->state());
   }
 }
 
 TransportResult
 TransportLayerLogging::SendPacket(const unsigned char *data, size_t len) {
   MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "SendPacket(" << len << ")");
 
   if (downward_) {
@@ -34,17 +34,17 @@ TransportLayerLogging::SendPacket(const 
   else {
     return static_cast<TransportResult>(len);
   }
 }
 
 void TransportLayerLogging::StateChange(TransportLayer *layer, State state) {
   MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Received StateChange to " << state);
 
-  SetState(state);
+  TL_SET_STATE(state);
 }
 
 void TransportLayerLogging::PacketReceived(TransportLayer* layer,
                                            const unsigned char *data,
                                            size_t len) {
   MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "PacketReceived(" << len << ")");
 
   SignalPacketReceived(this, data, len);
--- a/media/mtransport/transportlayerloopback.cpp
+++ b/media/mtransport/transportlayerloopback.cpp
@@ -52,17 +52,17 @@ nsresult TransportLayerLoopback::Init() 
 
   return NS_OK;
 }
 
 // Connect to the other side
 void TransportLayerLoopback::Connect(TransportLayerLoopback* peer) {
   peer_ = peer;
 
-  SetState(TS_OPEN);
+  TL_SET_STATE(TS_OPEN);
 }
 
 TransportResult
 TransportLayerLoopback::SendPacket(const unsigned char *data, size_t len) {
   MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "SendPacket(" << len << ")");
 
   if (!peer_) {
     MOZ_MTLOG(ML_ERROR, "Discarding packet because peer not attached");
--- a/media/mtransport/transportlayerprsock.cpp
+++ b/media/mtransport/transportlayerprsock.cpp
@@ -49,17 +49,17 @@ void TransportLayerPrsock::Import(PRFile
   handler_ = new SocketHandler(this, fd);
 
   nsresult rv = stservice_->AttachSocket(fd_, handler_);
   if (!NS_SUCCEEDED(rv)) {
     *result = rv;
     return;
   }
 
-  SetState(TS_OPEN);
+  TL_SET_STATE(TS_OPEN);
 
   *result = NS_OK;
 }
 
 int TransportLayerPrsock::SendPacket(const unsigned char *data, size_t len) {
   MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "SendPacket(" << len << ")");
   if (state_ != TS_OPEN) {
     MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Can't send packet on closed interface");
@@ -76,17 +76,17 @@ int TransportLayerPrsock::SendPacket(con
   PRErrorCode err = PR_GetError();
   if (err == PR_WOULD_BLOCK_ERROR) {
     MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Write blocked");
     return TE_WOULDBLOCK;
   }
 
 
   MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Write error; channel closed");
-  SetState(TS_ERROR);
+  TL_SET_STATE(TS_ERROR);
   return TE_ERROR;
 }
 
 void TransportLayerPrsock::OnSocketReady(PRFileDesc *fd, int16_t outflags) {
   if (!(outflags & PR_POLL_READ)) {
     return;
   }
 
@@ -96,21 +96,21 @@ void TransportLayerPrsock::OnSocketReady
   int32_t rv = PR_Read(fd, buf, sizeof(buf));
 
   if (rv > 0) {
     // Successful read
     MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Read " << rv << " bytes");
     SignalPacketReceived(this, buf, rv);
   } else if (rv == 0) {
     MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Read 0 bytes; channel closed");
-    SetState(TS_CLOSED);
+    TL_SET_STATE(TS_CLOSED);
   } else {
     PRErrorCode err = PR_GetError();
 
     if (err != PR_WOULD_BLOCK_ERROR) {
       MOZ_MTLOG(ML_DEBUG, LAYER_INFO << "Read error; channel closed");
-      SetState(TS_ERROR);
+      TL_SET_STATE(TS_ERROR);
     }
   }
 }
 
 NS_IMPL_ISUPPORTS0(TransportLayerPrsock::SocketHandler)
 }  // close namespace
--- a/media/mtransport/transportlayerprsock.h
+++ b/media/mtransport/transportlayerprsock.h
@@ -96,17 +96,17 @@ class TransportLayerPrsock : public Tran
   };
 
   // Allow SocketHandler to talk to our APIs
   friend class SocketHandler;
 
   // Functions to be called by SocketHandler
   void OnSocketReady(PRFileDesc *fd, int16_t outflags);
   void OnSocketDetached(PRFileDesc *fd) {
-    SetState(TS_CLOSED);
+    TL_SET_STATE(TS_CLOSED);
   }
   void IsLocal(bool *aIsLocal) {
     // TODO(jesup): better check? Does it matter? (likely no)
     *aIsLocal = false;
   }
 
   PRFileDesc *fd_;
   nsCOMPtr<SocketHandler> handler_;