Bug 1325536 - ice telemetry. r=bsmedberg,chutten,drno

MozReview-Commit-ID: 8pZBXA8Pjea

--HG--
extra : rebase_source : 37efe5b463098ff1489d317b1f78206cac4963b3

media/mtransport/nricectx.cpp

@@ -686,17 +686,51 @@ void NrIceCtx::internal_SetTimerAccelarator(int divider) {
   ctx_->test_timer_divider = divider;
 }
 
-NrIceCtx::~NrIceCtx() {
+void NrIceCtx::AccumulateStats(const NrIceStats& stats) {
+  nr_ice_accumulate_count(&(ctx_->stats.stun_retransmits),
+                          stats.stun_retransmits);
+  nr_ice_accumulate_count(&(ctx_->stats.turn_401s), stats.turn_401s);
+  nr_ice_accumulate_count(&(ctx_->stats.turn_403s), stats.turn_403s);
+  nr_ice_accumulate_count(&(ctx_->stats.turn_438s), stats.turn_438s);
+}
+
+NrIceStats NrIceCtx::Destroy() {
+  // designed to be called more than once so if stats are desired, this can be
+  // called just prior to the destructor
   MOZ_MTLOG(ML_DEBUG, "Destroying ICE ctx '" << name_ <<"'");
   for (auto stream = streams_.begin(); stream != streams_.end(); stream++) {
     if (*stream) {
       (*stream)->Close();
     }
   }
-  nr_ice_peer_ctx_destroy(&peer_);
-  nr_ice_ctx_destroy(&ctx_);
+
+  NrIceStats stats;
+  if (ctx_) {
+    stats.stun_retransmits = ctx_->stats.stun_retransmits;
+    stats.turn_401s = ctx_->stats.turn_401s;
+    stats.turn_403s = ctx_->stats.turn_403s;
+    stats.turn_438s = ctx_->stats.turn_438s;
+  }
+
+  if (peer_) {
+    nr_ice_peer_ctx_destroy(&peer_);
+  }
+  if (ctx_) {
+    nr_ice_ctx_destroy(&ctx_);
+  }
+
   delete ice_handler_vtbl_;
   delete ice_handler_;
+
+  ice_handler_vtbl_ = 0;
+  ice_handler_ = 0;
+  streams_.clear();
+
+  return stats;
+}
+
+NrIceCtx::~NrIceCtx() {
+  Destroy();
 }
 
 void

media/mtransport/nricectx.h

@@ -192,6 +192,14 @@ class NrIceProxyServer {
 
 class TestNat;
 
+class NrIceStats {
+ public:
+  uint16_t stun_retransmits;
+  uint16_t turn_401s;
+  uint16_t turn_403s;
+  uint16_t turn_438s;
+};
+
 class NrIceCtx {
  friend class NrIceCtxHandler;
  public:
@@ -322,6 +330,9 @@ class NrIceCtx {
   // more forking.
   nsresult Finalize();
 
+  void AccumulateStats(const NrIceStats& stats);
+  NrIceStats Destroy();
+
   // Are we trickling?
   bool generating_trickle() const { return trickle_; }
 

media/mtransport/nricectxhandler.cpp

@@ -141,6 +141,12 @@ NrIceCtxHandler::BeginIceRestart(RefPtr<NrIceCtx> new_ctx)
 void
 NrIceCtxHandler::FinalizeIceRestart()
 {
+  if (old_ctx) {
+    // Fixup the telemetry by transferring old stats to current ctx.
+    NrIceStats stats = old_ctx->Destroy();
+    current_ctx->AccumulateStats(stats);
+  }
+
   // no harm calling this even if we're not in the middle of restarting
   old_ctx = nullptr;
 }
@@ -156,5 +162,30 @@ NrIceCtxHandler::RollbackIceRestart()
   old_ctx = nullptr;
 }
 
+NrIceStats NrIceCtxHandler::Destroy()
+{
+  NrIceStats stats;
+
+  // designed to be called more than once so if stats are desired, this can be
+  // called just prior to the destructor
+  if (old_ctx && current_ctx) {
+    stats = old_ctx->Destroy();
+    current_ctx->AccumulateStats(stats);
+  }
+
+  if (current_ctx) {
+    stats = current_ctx->Destroy();
+  }
+
+  old_ctx = nullptr;
+  current_ctx = nullptr;
+
+  return stats;
+}
+
+NrIceCtxHandler::~NrIceCtxHandler()
+{
+  Destroy();
+}
 
 } // close namespace

media/mtransport/nricectxhandler.h

@@ -31,6 +31,7 @@ public:
   void FinalizeIceRestart();
   void RollbackIceRestart();
 
+  NrIceStats Destroy();
 
   NS_INLINE_DECL_THREADSAFE_REFCOUNTING(NrIceCtxHandler)
 
@@ -39,7 +40,7 @@ private:
                   bool offerer,
                   NrIceCtx::Policy policy);
   NrIceCtxHandler() = delete;
-  ~NrIceCtxHandler() {}
+  ~NrIceCtxHandler();
   DISALLOW_COPY_ASSIGN(NrIceCtxHandler);
 
   RefPtr<NrIceCtx> current_ctx;

media/mtransport/third_party/nICEr/src/ice/ice_candidate.c

@@ -321,6 +321,20 @@ int nr_ice_candidate_destroy(nr_ice_candidate **candp)
         break;
 #ifdef USE_TURN
       case RELAYED:
+        // record stats back to the ice ctx on destruction
+        if (cand->u.relayed.turn) {
+          nr_ice_accumulate_count(&(cand->ctx->stats.turn_401s), cand->u.relayed.turn->cnt_401s);
+          nr_ice_accumulate_count(&(cand->ctx->stats.turn_403s), cand->u.relayed.turn->cnt_403s);
+          nr_ice_accumulate_count(&(cand->ctx->stats.turn_438s), cand->u.relayed.turn->cnt_438s);
+
+          nr_turn_stun_ctx* stun_ctx;
+          stun_ctx = STAILQ_FIRST(&cand->u.relayed.turn->stun_ctxs);
+          while (stun_ctx) {
+            nr_ice_accumulate_count(&(cand->ctx->stats.stun_retransmits), stun_ctx->stun->retransmit_ct);
+
+            stun_ctx = STAILQ_NEXT(stun_ctx, entry);
+          }
+        }
         if (cand->u.relayed.turn_handle)
           nr_ice_socket_deregister(cand->isock, cand->u.relayed.turn_handle);
         if (cand->u.relayed.srvflx_candidate)

media/mtransport/third_party/nICEr/src/ice/ice_candidate_pair.c

@@ -152,6 +152,11 @@ int nr_ice_candidate_pair_destroy(nr_ice_cand_pair **pairp)
     pair=*pairp;
     *pairp=0;
 
+    // record stats back to the ice ctx on destruction
+    if (pair->stun_client) {
+      nr_ice_accumulate_count(&(pair->local->ctx->stats.stun_retransmits), pair->stun_client->retransmit_ct);
+    }
+
     RFREE(pair->as_string);
     RFREE(pair->foundation);
     nr_ice_socket_deregister(pair->local->isock,pair->stun_client_handle);

media/mtransport/third_party/nICEr/src/ice/ice_ctx.c

@@ -1055,3 +1055,16 @@ int nr_ice_get_new_ice_pwd(char** pwd)
     return(_status);
   }
 
+#ifndef UINT2_MAX
+#define UINT2_MAX ((UINT2)(65535U))
+#endif
+
+void nr_ice_accumulate_count(UINT2* orig_count, UINT2 new_count)
+  {
+    if (UINT2_MAX - new_count < *orig_count) {
+      // don't rollover, just stop accumulating at MAX value
+      *orig_count = UINT2_MAX;
+    } else {
+      *orig_count += new_count;
+    }
+  }

media/mtransport/third_party/nICEr/src/ice/ice_ctx.h

@@ -112,6 +112,13 @@ typedef struct nr_ice_stun_id_ {
 
 typedef STAILQ_HEAD(nr_ice_stun_id_head_,nr_ice_stun_id_) nr_ice_stun_id_head;
 
+typedef struct nr_ice_stats_ {
+  UINT2 stun_retransmits;
+  UINT2 turn_401s;
+  UINT2 turn_403s;
+  UINT2 turn_438s;
+} nr_ice_stats;
+
 struct nr_ice_ctx_ {
   UINT4 flags;
   char *label;
@@ -155,6 +162,7 @@ struct nr_ice_ctx_ {
   void *trickle_cb_arg;
 
   char force_net_interface[MAXIFNAME];
+  nr_ice_stats stats;
 };
 
 int nr_ice_ctx_create(char *label, UINT4 flags, nr_ice_ctx **ctxp);
@@ -192,6 +200,8 @@ int nr_ice_ctx_set_trickle_cb(nr_ice_ctx *ctx, nr_ice_trickle_candidate_cb cb, v
 int nr_ice_ctx_hide_candidate(nr_ice_ctx *ctx, nr_ice_candidate *cand);
 int nr_ice_get_new_ice_ufrag(char** ufrag);
 int nr_ice_get_new_ice_pwd(char** pwd);
+// accumulate a count without worrying about rollover
+void nr_ice_accumulate_count(UINT2* orig_count, UINT2 new_count);
 
 #define NR_ICE_MAX_ATTRIBUTE_SIZE 256
 

media/mtransport/third_party/nICEr/src/stun/stun_client_ctx.c

@@ -252,6 +252,9 @@ static void nr_stun_client_timer_expired_cb(NR_SOCKET s, int b, void *cb_arg)
     if (ctx->state != NR_STUN_CLIENT_STATE_RUNNING)
         ABORT(R_NOT_PERMITTED);
 
+    // track retransmits for ice telemetry
+    nr_ice_accumulate_count(&(ctx->retransmit_ct), 1);
+
     /* as a side effect will reset the timer */
     nr_stun_client_send_request(ctx);
 

media/mtransport/third_party/nICEr/src/stun/stun_client_ctx.h

@@ -168,6 +168,7 @@ struct nr_stun_client_ctx_ {
   char *realm;
   void *timer_handle;
   int request_ct;
+  UINT2 retransmit_ct;
   UINT4 rto_ms;    /* retransmission time out */
   double retransmission_backoff_factor;
   UINT4 maximum_transmits;

media/mtransport/third_party/nICEr/src/stun/turn_client_ctx.c

@@ -255,8 +255,16 @@ static void nr_turn_stun_ctx_cb(NR_SOCKET s, int how, void *arg)
          paradigm. After that, we fail */
       /* TODO(ekr@rtfm.com): 401 needs a #define */
       /* TODO(ekr@rtfm.com): Add alternate-server (Mozilla bug 857688) */
+      if (ctx->stun->error_code == 438) {
+        // track 438s for ice telemetry
+        nr_ice_accumulate_count(&(ctx->tctx->cnt_438s), 1);
+      }
       if (ctx->stun->error_code == 401 || ctx->stun->error_code == 438) {
         if (ctx->retry_ct > 0) {
+          if (ctx->stun->error_code == 401) {
+            // track 401s for ice telemetry
+            nr_ice_accumulate_count(&(ctx->tctx->cnt_401s), 1);
+          }
           r_log(NR_LOG_TURN, LOG_WARNING, "TURN(%s): Exceeded the number of retries", ctx->tctx->label);
           ABORT(R_FAILED);
         }
@@ -606,6 +614,8 @@ static void nr_turn_client_permission_error_cb(NR_SOCKET s, int how, void *arg)
   nr_turn_stun_ctx *ctx = (nr_turn_stun_ctx *)arg;
 
   if (ctx->last_error_code == 403) {
+    // track 403s for ice telemetry
+    nr_ice_accumulate_count(&(ctx->tctx->cnt_403s), 1);
     r_log(NR_LOG_TURN, LOG_WARNING, "TURN(%s): mode %d, permission denied",
           ctx->tctx->label, ctx->mode);
 

media/mtransport/third_party/nICEr/src/stun/turn_client_ctx.h

@@ -101,6 +101,11 @@ typedef struct nr_turn_client_ctx_ {
 
   void *connected_timer_handle;
   void *refresh_timer_handle;
+
+  // ice telemetry
+  UINT2 cnt_401s;
+  UINT2 cnt_403s;
+  UINT2 cnt_438s;
 } nr_turn_client_ctx;
 
 extern int NR_LOG_TURN;

media/webrtc/signaling/src/peerconnection/PeerConnectionMedia.cpp

@@ -53,6 +53,7 @@
 #include "MediaStreamList.h"
 #include "nsIScriptGlobalObject.h"
 #include "mozilla/Preferences.h"
+#include "mozilla/Telemetry.h"
 #include "mozilla/dom/RTCStatsReportBinding.h"
 #include "MediaStreamTrack.h"
 #include "VideoStreamTrack.h"
@@ -791,6 +792,11 @@ PeerConnectionMedia::RollbackIceRestart_s()
 
   mIceCtxHdlr->RollbackIceRestart();
   ConnectSignals(mIceCtxHdlr->ctx().get(), restartCtx.get());
+
+  // Fixup the telemetry by transferring abandoned ctx stats to current ctx.
+  NrIceStats stats = restartCtx->Destroy();
+  restartCtx = nullptr;
+  mIceCtxHdlr->ctx()->AccumulateStats(stats);
 }
 
 bool
@@ -1101,6 +1107,25 @@ PeerConnectionMedia::ShutdownMediaTransport_s()
 
   disconnect_all();
   mTransportFlows.clear();
+
+#if !defined(MOZILLA_EXTERNAL_LINKAGE)
+  NrIceStats stats = mIceCtxHdlr->Destroy();
+
+  CSFLogDebug(logTag, "Ice Telemetry: stun (retransmits: %d)"
+                      "   turn (401s: %d   403s: %d   438s: %d)",
+              stats.stun_retransmits, stats.turn_401s, stats.turn_403s,
+              stats.turn_438s);
+
+  Telemetry::ScalarAdd(Telemetry::ScalarID::WEBRTC_NICER_STUN_RETRANSMITS,
+                       stats.stun_retransmits);
+  Telemetry::ScalarAdd(Telemetry::ScalarID::WEBRTC_NICER_TURN_401S,
+                       stats.turn_401s);
+  Telemetry::ScalarAdd(Telemetry::ScalarID::WEBRTC_NICER_TURN_403S,
+                       stats.turn_403s);
+  Telemetry::ScalarAdd(Telemetry::ScalarID::WEBRTC_NICER_TURN_438S,
+                       stats.turn_438s);
+#endif
+
   mIceCtxHdlr = nullptr;
 
   mMainThread->Dispatch(WrapRunnable(this, &PeerConnectionMedia::SelfDestruct_m),

toolkit/components/telemetry/Scalars.yaml

@@ -320,3 +320,78 @@ telemetry.test:
       - telemetry-client-dev@mozilla.com
     record_in_processes:
       - 'all_childs'
+
+# The following section contains WebRTC nICEr scalars
+# For more info on ICE, see https://tools.ietf.org/html/rfc5245
+# For more info on STUN, see https://tools.ietf.org/html/rfc5389
+# For more info on TURN, see https://tools.ietf.org/html/rfc5766
+webrtc.nicer:
+  stun_retransmits:
+    bug_numbers:
+      - 1325536
+    description: >
+      The count of STUN message retransmissions during a WebRTC call.
+      When sending STUN request messages over UDP, messages may be
+      dropped by the network. Retransmissions are the mechanism used to
+      accomplish reliability of the STUN request/response transaction.
+      This can happen during both successful and unsuccessful WebRTC
+      calls.
+      For more info on ICE, see https://tools.ietf.org/html/rfc5245
+      For more info on STUN, see https://tools.ietf.org/html/rfc5389
+      For more info on TURN, see https://tools.ietf.org/html/rfc5766
+    expires: "57"
+    kind: uint
+    notification_emails:
+      - webrtc-ice-telemetry-alerts@mozilla.com
+    release_channel_collection: opt-in
+
+  turn_401s:
+    bug_numbers:
+      - 1325536
+    description: >
+      The count of TURN 401 (Unauthorized) responses to allocation
+      requests. Only 401 responses beyond the first, expected 401 are
+      counted. More than one 401 repsonse indicates the client is
+      experiencing difficulty authenticating with the TURN server. This
+      can happen during both successful and unsuccessful WebRTC calls.
+      For more info on ICE, see https://tools.ietf.org/html/rfc5245
+      For more info on STUN, see https://tools.ietf.org/html/rfc5389
+      For more info on TURN, see https://tools.ietf.org/html/rfc5766
+    expires: "57"
+    kind: uint
+    notification_emails:
+      - webrtc-ice-telemetry-alerts@mozilla.com
+    release_channel_collection: opt-in
+
+  turn_403s:
+    bug_numbers:
+      - 1325536
+    description: >
+      The count of TURN 403 (Forbidden) responses to CreatePermission or
+      ChannelBind requests.  This indicates that the TURN server is
+      refusing the request for an IP address or IP address/port
+      combination, likely due to administrative restrictions.
+      For more info on ICE, see https://tools.ietf.org/html/rfc5245
+      For more info on STUN, see https://tools.ietf.org/html/rfc5389
+      For more info on TURN, see https://tools.ietf.org/html/rfc5766
+    expires: "57"
+    kind: uint
+    notification_emails:
+      - webrtc-ice-telemetry-alerts@mozilla.com
+    release_channel_collection: opt-in
+
+  turn_438s:
+    bug_numbers:
+      - 1325536
+    description: >
+      The count of TURN 438 (Stale Nonce) responses to allocation
+      requests. This can happen during both successful and unsuccessful
+      WebRTC calls.
+      For more info on ICE, see https://tools.ietf.org/html/rfc5245
+      For more info on STUN, see https://tools.ietf.org/html/rfc5389
+      For more info on TURN, see https://tools.ietf.org/html/rfc5766
+    expires: "57"
+    kind: uint
+    notification_emails:
+      - webrtc-ice-telemetry-alerts@mozilla.com
+    release_channel_collection: opt-in