Bug 906990 - Part 3: Make it easier to filter out logging related to a given candidate pair r=ekr
authorByron Campen [:bwc] <docfaraday@gmail.com>
Mon, 14 Oct 2013 10:00:41 -0700
changeset 150703 10c7b809dfb161e6aa2b24fececfbee40403f82b
parent 150702 e93223d403fee9656b424826f41cbf594a3cb687
child 150704 fa8afb1865a195058c7755703927466b0e5d4bf0
push id25462
push userkwierso@gmail.com
push dateTue, 15 Oct 2013 01:48:30 +0000
treeherdermozilla-central@ddd03c32fab1 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersekr
bugs906990
milestone27.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 906990 - Part 3: Make it easier to filter out logging related to a given candidate pair r=ekr
media/mtransport/third_party/nICEr/src/ice/ice_candidate.c
media/mtransport/third_party/nICEr/src/ice/ice_candidate_pair.c
media/mtransport/third_party/nICEr/src/ice/ice_component.c
media/mtransport/third_party/nICEr/src/stun/stun_client_ctx.c
--- a/media/mtransport/third_party/nICEr/src/ice/ice_candidate.c
+++ b/media/mtransport/third_party/nICEr/src/ice/ice_candidate.c
@@ -206,18 +206,18 @@ int nr_ice_peer_peer_rflx_candidate_crea
     cand->state=NR_ICE_CAND_STATE_INITIALIZED;
     cand->ctx=ctx;
     cand->type=ctype;
     cand->component_id=comp->component_id;
     cand->component=comp;
     cand->stream=comp->stream;
 
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s): creating candidate %s with type %d",
-      ctx->label,label,ctype);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s)/CAND(%s): creating candidate with type %s",
+      ctx->label,label,nr_ctype_name(ctype));
 
     if(r=nr_transport_addr_copy(&cand->base,addr))
       ABORT(r);
     if(r=nr_transport_addr_copy(&cand->addr,addr))
       ABORT(r);
     /* Bogus foundation */
     if(!(cand->foundation=r_strdup(cand->addr.as_string)))
       ABORT(r);
@@ -658,17 +658,17 @@ static int nr_ice_start_relay_turn(nr_ic
   }
 #endif /* USE_TURN */
 
 static void nr_ice_srvrflx_stun_finished_cb(NR_SOCKET sock, int how, void *cb_arg)
   {
     int _status;
     nr_ice_candidate *cand=cb_arg;
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s): %s for %s",cand->ctx->label,__FUNCTION__,cand->label);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s)/CAND(%s): %s",cand->ctx->label,cand->label,__FUNCTION__);
 
     /* Deregister to suppress duplicates */
     if(cand->u.srvrflx.stun_handle){ /* This test because we might have failed before CB registered */
       nr_ice_socket_deregister(cand->isock,cand->u.srvrflx.stun_handle);
       cand->u.srvrflx.stun_handle=0;
     }
 
     switch(cand->u.srvrflx.stun->state){
@@ -711,27 +711,27 @@ static void nr_ice_turn_allocated_cb(NR_
       case NR_TURN_CLIENT_STATE_ALLOCATED:
         if (r=nr_turn_client_get_relayed_address(turn, &relay_addr))
           ABORT(r);
 
         if(r=nr_concat_strings(&label,"turn-relay(",cand->base.as_string,"|",
                                relay_addr.as_string,")",NULL))
           ABORT(r);
 
-        r_log(LOG_ICE,LOG_DEBUG,"ICE(%s): Switching from TURN (%s) to RELAY (%s)",cand->u.relayed.turn->label,cand->label,label);
+        r_log(LOG_ICE,LOG_DEBUG,"TURN-CLIENT(%s)/CAND(%s): Switching from TURN to RELAY (%s)",cand->u.relayed.turn->label,cand->label,label);
 
         /* Copy the relayed address into the candidate addr and
            into the candidate base. Note that we need to keep the
            ifname in the base. */
         if (r=nr_transport_addr_copy(&cand->addr, &relay_addr))
           ABORT(r);
         if (r=nr_transport_addr_copy_keep_ifname(&cand->base, &relay_addr))  /* Need to keep interface for priority calculation */
           ABORT(r);
 
-        r_log(LOG_ICE,LOG_DEBUG,"ICE-CANDIDATE(%s): base=%s, candidate=%s", cand->label, cand->base.as_string, cand->addr.as_string);
+        r_log(LOG_ICE,LOG_DEBUG,"ICE(%s)/CAND(%s): new relay base=%s addr=%s", cand->ctx->label, cand->label, cand->base.as_string, cand->addr.as_string);
 
         RFREE(cand->label);
         cand->label=label;
         cand->state=NR_ICE_CAND_STATE_INITIALIZED;
 
         /* Execute the ready callback */
         cand->done_cb(0,0,cand->cb_arg);
 
--- a/media/mtransport/third_party/nICEr/src/ice/ice_candidate_pair.c
+++ b/media/mtransport/third_party/nICEr/src/ice/ice_candidate_pair.c
@@ -83,17 +83,22 @@ int nr_ice_candidate_pair_create(nr_ice_
     }
     else{
       o_priority=rcand->priority;
       a_priority=lcand->priority;
     }
     pair->priority=(MIN(o_priority, a_priority))<<32 |
       (MAX(o_priority, a_priority))<<1 | (o_priority > a_priority?0:1);
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s): Pairing candidate %s (%x):%s (%x) priority=%llu (%llx) codeword=%s",pctx->ctx->label,lcand->addr.as_string,lcand->priority,rcand->addr.as_string,rcand->priority,pair->priority,pair->priority,pair->codeword);
+    /*
+       TODO(bcampen@mozilla.com): Would be nice to log why this candidate was
+       created (initial pair generation, triggered check, and new trickle
+       candidate seem to be the possibilities here).
+    */
+    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s)/CAND-PAIR(%s): Pairing candidate %s (%x):%s (%x) priority=%llu (%llx)",pctx->ctx->label,pair->codeword,lcand->addr.as_string,lcand->priority,rcand->addr.as_string,rcand->priority,pair->priority,pair->priority);
 
     /* Foundation */
     if(r=nr_concat_strings(&pair->foundation,lcand->foundation,"|",
       rcand->foundation,NULL))
       ABORT(r);
 
     /* Compute the RTO per S 16 */
     RTO = MAX(100, (pctx->ctx->Ta * pctx->waiting_pairs));
@@ -179,30 +184,30 @@ static void nr_ice_candidate_pair_stun_c
     nr_transport_addr *request_src;
     nr_transport_addr *request_dst;
     nr_transport_addr *response_src;
     nr_transport_addr response_dst;
     nr_stun_message_attribute *attr;
 
     pair->stun_cb_timer=0;
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s): STUN cb on pair %s",
-      pair->pctx->label,pair->local->stream->label,pair->as_string);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/CAND-PAIR(%s): STUN cb on pair addr = %s",
+      pair->pctx->label,pair->local->stream->label,pair->codeword,pair->as_string);
 
     /* This ordinarily shouldn't happen, but can if we're
        doing the second check to confirm nomination.
        Just bail out */
     if(pair->state==NR_ICE_PAIR_STATE_SUCCEEDED)
       goto done;
 
     switch(pair->stun_client->state){
       case NR_STUN_CLIENT_STATE_FAILED:
         sres=pair->stun_client->response;
         if(sres && nr_stun_message_has_attribute(sres,NR_STUN_ATTR_ERROR_CODE,&attr)&&attr->u.error_code.number==487){
-          r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s): detected role conflict. Switching to controlled",pair->pctx->label);
+          r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s)/CAND-PAIR(%s): detected role conflict. Switching to controlled",pair->pctx->label,pair->codeword);
 
           pair->pctx->controlling=0;
 
           /* Only restart if we haven't tried this already */
           if(!pair->restart_controlled_cb_timer)
             NR_ASYNC_TIMER_SET(0,nr_ice_candidate_pair_restart_stun_controlled_cb,pair,&pair->restart_controlled_cb_timer);
 
           return;
@@ -211,37 +216,37 @@ static void nr_ice_candidate_pair_stun_c
       case NR_STUN_CLIENT_STATE_TIMED_OUT:
         nr_ice_candidate_pair_set_state(pair->pctx,pair,NR_ICE_PAIR_STATE_FAILED);
         break;
       case NR_STUN_CLIENT_STATE_DONE:
         /* make sure the addresses match up S 7.1.2.2 */
         response_src=&pair->stun_client->peer_addr;
         request_dst=&pair->remote->addr;
         if (nr_transport_addr_cmp(response_src,request_dst,NR_TRANSPORT_ADDR_CMP_MODE_ALL)){
-          r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s): Peer address mismatch %s/%s",pair->pctx->label, response_src->as_string,request_dst->as_string);
+          r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/CAND-PAIR(%s): Peer address mismatch %s != %s",pair->pctx->label,pair->codeword,response_src->as_string,request_dst->as_string);
           nr_ice_candidate_pair_set_state(pair->pctx,pair,NR_ICE_PAIR_STATE_FAILED);
           break;
         }
         request_src=&pair->stun_client->my_addr;
         nr_socket_getaddr(pair->local->osock,&response_dst);
         if (nr_transport_addr_cmp(request_src,&response_dst,NR_TRANSPORT_ADDR_CMP_MODE_ALL)){
-          r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s): Address mismatch %s/%s",pair->pctx->label, request_src->as_string,response_dst.as_string);
+          r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/CAND-PAIR(%s): Local address mismatch %s != %s",pair->pctx->label,pair->codeword,request_src->as_string,response_dst.as_string);
           nr_ice_candidate_pair_set_state(pair->pctx,pair,NR_ICE_PAIR_STATE_FAILED);
           break;
         }
 
         if(strlen(pair->stun_client->results.ice_binding_response.mapped_addr.as_string)==0){
           /* we're using the mapped_addr returned by the server to lookup our
            * candidate, but if the server fails to do that we can't perform
            * the lookup -- this may be a BUG because if we've gotten here
            * then the transaction ID check succeeded, and perhaps we should
            * just assume that it's the server we're talking to and that our
            * peer is ok, but I'm not sure how that'll interact with the
            * peer reflexive logic below */
-          r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s): server failed to return mapped address on pair %s", pair->pctx->label,pair->as_string);
+          r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s)/CAND-PAIR(%s): server failed to return mapped address on pair %s", pair->pctx->label,pair->codeword,pair->as_string);
           nr_ice_candidate_pair_set_state(pair->pctx,pair,NR_ICE_PAIR_STATE_FAILED);
           break;
         }
         else if(!nr_transport_addr_cmp(&pair->local->addr,&pair->stun_client->results.ice_binding_response.mapped_addr,NR_TRANSPORT_ADDR_CMP_MODE_ALL)){
           nr_ice_candidate_pair_set_state(pair->pctx,pair,NR_ICE_PAIR_STATE_SUCCEEDED);
         }
         else{
           /* OK, this didn't correspond to a pair on the check list, but
@@ -373,17 +378,17 @@ int nr_ice_candidate_pair_start(nr_ice_p
     return(_status);
   }
 
 
 int nr_ice_candidate_pair_do_triggered_check(nr_ice_peer_ctx *pctx, nr_ice_cand_pair *pair)
   {
     int r,_status;
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s): triggered check on %s",pctx->label,pair->as_string);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/CAND-PAIR(%s): triggered check on %s",pctx->label,pair->codeword,pair->as_string);
 
     switch(pair->state){
       case NR_ICE_PAIR_STATE_FROZEN:
         nr_ice_candidate_pair_set_state(pctx,pair,NR_ICE_PAIR_STATE_WAITING);
         /* Fall through */
       case NR_ICE_PAIR_STATE_WAITING:
         /* Start the checks */
         if(r=nr_ice_candidate_pair_start(pctx,pair))
@@ -426,17 +431,17 @@ int nr_ice_candidate_pair_select(nr_ice_
     int r,_status;
 
     if(!pair){
       r_log(LOG_ICE,LOG_ERR,"ICE-PAIR: No pair chosen");
       ABORT(R_BAD_ARGS);
     }
 
     if(pair->state!=NR_ICE_PAIR_STATE_SUCCEEDED){
-      r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s): tried to install non-succeeded pair %s, ignoring",pair->pctx->label,pair->as_string);
+      r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s)/CAND-PAIR(%s): tried to install non-succeeded pair, ignoring: %s",pair->pctx->label,pair->codeword,pair->as_string);
     }
     else{
       /* Ok, they chose one */
       /* 1. Send a new request with nominated. Do it as a scheduled
             event to avoid reentrancy issues. Only do this if it hasn't
             happened already (though this shouldn't happen.)
       */
       if(!pair->restart_nominated_cb_timer)
@@ -451,18 +456,18 @@ int nr_ice_candidate_pair_select(nr_ice_
   abort:
     return(_status);
  }
 
 int nr_ice_candidate_pair_set_state(nr_ice_peer_ctx *pctx, nr_ice_cand_pair *pair, int state)
   {
     int r,_status;
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s): setting pair %s to %s",
-      pctx->label,pair->as_string,nr_ice_cand_pair_states[state]);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/CAND-PAIR(%s): setting pair to state %s: %s",
+      pctx->label,pair->codeword,nr_ice_cand_pair_states[state],pair->as_string);
 
     /* NOTE: This function used to reference pctx->state instead of
        pair->state and the assignment to pair->state was at the top
        of this function. Because pctx->state was never changed, this seems to have
        been a typo. The natural logic is "if the state changed
        decrement the counter" so this implies we should be checking
        the pair state rather than the pctx->state.
 
@@ -492,17 +497,17 @@ int nr_ice_candidate_pair_set_state(nr_i
 
     _status=0;
   abort:
     return(_status);
   }
 
 int nr_ice_candidate_pair_dump_state(nr_ice_cand_pair *pair, FILE *out)
   {
-    //r_log(LOG_ICE,LOG_DEBUG,"pair %s: state=%s, priority=0x%llx\n",pair->as_string,nr_ice_cand_pair_states[pair->state],pair->priority);
+    /*r_log(LOG_ICE,LOG_DEBUG,"CAND-PAIR(%s): pair %s: state=%s, priority=0x%llx\n",pair->codeword,pair->as_string,nr_ice_cand_pair_states[pair->state],pair->priority);*/
 
     return(0);
   }
 
 
 int nr_ice_candidate_pair_insert(nr_ice_cand_pair_head *head,nr_ice_cand_pair *pair)
   {
     nr_ice_cand_pair *c1;
@@ -523,17 +528,17 @@ int nr_ice_candidate_pair_insert(nr_ice_
 
 void nr_ice_candidate_pair_restart_stun_nominated_cb(NR_SOCKET s, int how, void *cb_arg)
   {
     nr_ice_cand_pair *pair=cb_arg;
     int r,_status;
 
     pair->restart_nominated_cb_timer=0;
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s):%d: Restarting pair %s as nominated",pair->pctx->label,pair->local->stream->label,pair->remote->component->component_id,pair->as_string);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/CAND-PAIR(%s)/COMP(%d): Restarting pair as nominated: %s",pair->pctx->label,pair->local->stream->label,pair->codeword,pair->remote->component->component_id,pair->as_string);
 
     nr_stun_client_reset(pair->stun_client);
 
     if(r=nr_stun_client_start(pair->stun_client,NR_ICE_CLIENT_MODE_USE_CANDIDATE,nr_ice_candidate_pair_stun_cb,pair))
       ABORT(r);
 
     if(r=nr_ice_ctx_remember_id(pair->pctx->ctx, pair->stun_client->request))
       ABORT(r);
@@ -545,17 +550,17 @@ void nr_ice_candidate_pair_restart_stun_
 
 static void nr_ice_candidate_pair_restart_stun_controlled_cb(NR_SOCKET s, int how, void *cb_arg)
   {
     nr_ice_cand_pair *pair=cb_arg;
     int r,_status;
 
     pair->restart_controlled_cb_timer=0;
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s):%d: Restarting pair %s as CONTROLLED",pair->pctx->label,pair->local->stream->label,pair->remote->component->component_id,pair->as_string);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/CAND-PAIR(%s):COMP(%d): Restarting pair as CONTROLLED: %s",pair->pctx->label,pair->local->stream->label,pair->codeword,pair->remote->component->component_id,pair->as_string);
 
     nr_stun_client_reset(pair->stun_client);
     pair->stun_client->params.ice_binding_request.control=NR_ICE_CONTROLLED;
 
     if(r=nr_stun_client_start(pair->stun_client,NR_ICE_CLIENT_MODE_BINDING_REQUEST,nr_ice_candidate_pair_stun_cb,pair))
       ABORT(r);
 
     if(r=nr_ice_ctx_remember_id(pair->pctx->ctx, pair->stun_client->request))
--- a/media/mtransport/third_party/nICEr/src/ice/ice_component.c
+++ b/media/mtransport/third_party/nICEr/src/ice/ice_component.c
@@ -181,20 +181,20 @@ int nr_ice_component_initialize(struct n
     char *lufrag;
     char *lpwd;
     Data pwd;
     int addr_ct=ctx->local_addr_ct;
     int i;
     int j;
     char label[256];
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s): initializing component with id %d",ctx->label,component->component_id);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s)/COMP(%d): initializing component",ctx->label,component->component_id);
 
     if(addr_ct==0){
-      r_log(LOG_ICE,LOG_ERR,"ICE(%s): no local addresses available",ctx->label);
+      r_log(LOG_ICE,LOG_ERR,"ICE(%s)/COMP(%d): no local addresses available",ctx->label, component->component_id);
       ABORT(R_NOT_FOUND);
     }
 
     /* Now one ice_socket for each address */
     for(i=0;i<addr_ct;i++){
       char suppress;
 
       if(r=NR_reg_get2_char(NR_ICE_REG_SUPPRESS_INTERFACE_PRFX,addrs[i].addr.ifname,&suppress)){
@@ -372,17 +372,17 @@ int nr_ice_component_maybe_prune_candida
           break;
         }
       }
 
       c2=TAILQ_NEXT(c2,entry_comp);
     }
 
     if (tmp) {
-      r_log(LOG_ICE,LOG_DEBUG,"ICE(%s): Removing redundant candidate %s",
+      r_log(LOG_ICE,LOG_DEBUG,"ICE(%s)/CAND(%s): Removing redundant candidate",
             ctx->label,tmp->label);
 
       TAILQ_REMOVE(&comp->candidates,tmp,entry_comp);
       comp->candidate_ct--;
       TAILQ_REMOVE(&tmp->isock->candidates,tmp,entry_sock);
 
       nr_ice_candidate_destroy(&tmp);
     }
@@ -398,17 +398,17 @@ static int nr_ice_component_process_inco
     nr_stun_message *sreq=req->request;
     nr_stun_message_attribute *attr;
     int component_id_matched;
     int local_addr_matched;
     int remote_addr_matched;
     nr_ice_cand_pair *found_invalid=0;
     int r=0,_status;
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)(%d): received request from %s",comp->stream->pctx->label,comp->stream->label,comp->component_id,req->src_addr.as_string);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/COMP(%d): received request from %s",comp->stream->pctx->label,comp->stream->label,comp->component_id,req->src_addr.as_string);
 
     if (comp->state == NR_ICE_COMPONENT_DISABLED)
       ABORT(R_REJECTED);
 
     /* Check for role conficts (7.2.1.1) */
     if(comp->stream->pctx->controlling){
       if(nr_stun_message_has_attribute(sreq,NR_STUN_ATTR_ICE_CONTROLLING,&attr)){
         /* OK, there is a conflict. Who's right? */
@@ -472,17 +472,17 @@ static int nr_ice_component_process_inco
       remote_addr_matched = 1;
 
       if(pair->state==NR_ICE_PAIR_STATE_FAILED){
         found_invalid=pair;
         goto next_pair;
       }
 
       if (local_addr_matched && remote_addr_matched){
-        r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s): Found a matching pair: %s",comp->stream->pctx->label,pair->as_string);
+        r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/CAND_PAIR(%s): Found a matching pair for received check: %s",comp->stream->pctx->label,pair->codeword,pair->as_string);
         break; /* OK, this is a known pair */
       }
 
     next_pair:
       pair=TAILQ_NEXT(pair,entry);
     }
 
     if(!pair){
@@ -538,48 +538,48 @@ static int nr_ice_component_process_inco
       }
       else{
         /* OK, there was a pair, it's just invalid: According to Section
            7.2.1.4, we need to resurrect it
         */
         if(found_invalid->state == NR_ICE_PAIR_STATE_FAILED){
           pair=found_invalid;
 
-          r_log(LOG_ICE,LOG_WARNING,"ICE-PEER(%s): received STUN check on invalid pair %s: resurrecting",comp->stream->pctx->label,pair->as_string);
+          r_log(LOG_ICE,LOG_WARNING,"ICE-PEER(%s)/CAND-PAIR(%s): received STUN check on invalid pair, resurrecting: %s",comp->stream->pctx->label,pair->codeword,pair->as_string);
           nr_ice_candidate_pair_set_state(pair->pctx,pair,NR_ICE_PAIR_STATE_WAITING);
         }
         else{
           /* This shouldn't happen */
-          r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s): received STUN check on invalid pair %s but not in FAILED state",comp->stream->pctx->label,pair->as_string);
+          r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s)/CAND-PAIR(%s): received STUN check on invalid pair that was not in state FAILED; this should not happen: %s",comp->stream->pctx->label,pair->codeword,pair->as_string);
           *error=500;
           ABORT(R_BAD_DATA);
         }
       }
     }
 
     /* OK, we've got a pair to work with. Turn it on */
+    assert(pair);
     if(nr_stun_message_has_attribute(sreq,NR_STUN_ATTR_USE_CANDIDATE,0)){
       if(comp->stream->pctx->controlling){
-        r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s): Peer sent USE-CANDIDATE but is controlled",comp->stream->pctx->label);
+        r_log(LOG_ICE,LOG_ERR,"ICE-PEER(%s)/CAND_PAIR(%s): Peer sent USE-CANDIDATE but is controlled",comp->stream->pctx->label, pair->codeword);
       }
       else{
         /* If this is the first time we've noticed this is nominated...*/
         pair->peer_nominated=1;
 
         if(pair->state==NR_ICE_PAIR_STATE_SUCCEEDED && !pair->nominated){
           pair->nominated=1;
 
           if(r=nr_ice_component_nominated_pair(pair->remote->component, pair)) {
             *error=(r==R_NO_MEMORY)?500:400;
             ABORT(r);
           }
         }
       }
     }
-    assert(pair != 0);
 
     if(r=nr_ice_candidate_pair_do_triggered_check(comp->stream->pctx,pair)) {
       *error=(r==R_NO_MEMORY)?500:400;
       ABORT(r);
     }
 
     _status=0;
   abort:
@@ -615,26 +615,26 @@ int nr_ice_component_service_pre_answer_
   {
     nr_ice_pre_answer_request *r1,*r2;
     nr_ice_component *comp = pcomp->local_component;
     int r,_status;
 
     if (serviced)
       *serviced = 0;
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/comp(%d): looking for pre-answer requests",pctx->label,comp->stream->label,comp->component_id);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/COMP(%d): looking for pre-answer requests",pctx->label,comp->stream->label,comp->component_id);
 
     STAILQ_FOREACH_SAFE(r1, &comp->pre_answer_reqs, entry, r2) {
       if (!strcmp(r1->username, username)) {
         int error = 0;
 
-        r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/comp(%d): found pre-answer request",pctx->label,comp->stream->label,comp->component_id);
+        r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/COMP(%d): found pre-answer request",pctx->label,comp->stream->label,comp->component_id);
         r = nr_ice_component_process_incoming_check(pcomp, &r1->local_addr, &r1->req, &error);
         if (r) {
-          r_log(LOG_ICE,LOG_INFO,"ICE-PEER(%s)/STREAM(%s)/comp(%d): error processing pre-answer request. Would have returned %d",pctx->label,comp->stream->label,comp->component_id, error);
+          r_log(LOG_ICE,LOG_INFO,"ICE-PEER(%s)/STREAM(%s)/COMP(%d): error processing pre-answer request. Would have returned %d",pctx->label,comp->stream->label,comp->component_id, error);
         }
         (*serviced)++;
         STAILQ_REMOVE(&comp->pre_answer_reqs,r1,nr_ice_pre_answer_request_, entry);
         nr_ice_pre_answer_request_destroy(&r1);
       }
     }
 
     _status=0;
@@ -645,17 +645,17 @@ int nr_ice_component_service_pre_answer_
 int nr_ice_component_pair_candidate(nr_ice_peer_ctx *pctx, nr_ice_component *pcomp, nr_ice_candidate *lcand, int pair_all_remote)
   {
     int r, _status;
     nr_ice_candidate *pcand;
     nr_ice_cand_pair *pair=0;
     char codeword[5];
 
     nr_ice_compute_codeword(lcand->label,strlen(lcand->label),codeword);
-    r_log(LOG_ICE,LOG_DEBUG,"Pairing local candidate %s:%s",codeword,lcand->label);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/CAND(%s): Pairing local candidate %s",pctx->label,codeword,lcand->label);
 
     switch(lcand->type){
       case HOST:
         break;
       case SERVER_REFLEXIVE:
       case PEER_REFLEXIVE:
         /* Don't actually pair these candidates */
         goto done;
@@ -681,17 +681,17 @@ int nr_ice_component_pair_candidate(nr_i
       */
       if (pair_all_remote || (pcand->state == NR_ICE_CAND_PEER_CANDIDATE_UNPAIRED)) {
         /* If we are pairing our own trickle candidates, the remote candidate should
            all be paired */
         if (pair_all_remote)
           assert (pcand->state == NR_ICE_CAND_PEER_CANDIDATE_PAIRED);
 
         nr_ice_compute_codeword(pcand->label,strlen(pcand->label),codeword);
-        r_log(LOG_ICE,LOG_DEBUG,"Pairing with peer candidate %s:%s",codeword,pcand->label);
+        r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/CAND(%s): Pairing with peer candidate %s", pctx->label, codeword, pcand->label);
 
         if(r=nr_ice_candidate_pair_create(pctx,lcand,pcand,&pair))
           ABORT(r);
 
         if(r=nr_ice_candidate_pair_insert(&pcomp->stream->check_list,
                                           pair))
           ABORT(r);
       }
@@ -760,17 +760,17 @@ int nr_ice_component_pair_candidates(nr_
    component for use when we see the actual answer, at which point we need
    to do the procedures from S 7.2.1 in nr_ice_component_stun_server_cb.
  */
 static int nr_ice_component_stun_server_default_cb(void *cb_arg,nr_stun_server_ctx *stun_ctx,nr_socket *sock, nr_stun_server_request *req, int *dont_free, int *error)
   {
     int r, _status;
     nr_ice_component *comp = (nr_ice_component *)cb_arg;
     nr_ice_pre_answer_request *par = 0;
-    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s)/STREAM(%s)/comp(%d): Received STUN request pre-answer from %s",
+    r_log(LOG_ICE,LOG_DEBUG,"ICE(%s)/STREAM(%s)/COMP(%d): Received STUN request pre-answer from %s",
           comp->ctx->label, comp->stream->label, comp->component_id, req->src_addr.as_string);
 
     if (r=nr_ice_pre_answer_request_create(sock, req, &par))
       ABORT(r);
 
     *dont_free = 1;
     STAILQ_INSERT_TAIL(&comp->pre_answer_reqs, par, entry);
 
@@ -787,43 +787,43 @@ int nr_ice_component_nominated_pair(nr_i
 
     if(!comp->nominated)
       fire_cb=1;
 
     /* Are we changing what the nominated pair is? */
     if(comp->nominated){
       if(comp->nominated->priority > pair->priority)
         return(0);
-      r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/comp(%d): replacing pair %s with pair %s",comp->stream->pctx->label,comp->stream->label,comp->component_id,comp->nominated->as_string,pair->as_string);
+      r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/COMP(%d)/CAND-PAIR(%s): replacing pair %s with CAND-PAIR(%s)",comp->stream->pctx->label,comp->stream->label,comp->component_id,comp->nominated->codeword,comp->nominated->as_string,pair->codeword);
     }
 
     /* Set the new nominated pair */
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/comp(%d): nominated pair is %s (0x%p)",comp->stream->pctx->label,comp->stream->label,comp->component_id,pair->as_string,pair);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/COMP(%d)/CAND-PAIR(%s): nominated pair is %s",comp->stream->pctx->label,comp->stream->label,comp->component_id,pair->codeword,pair->as_string);
     comp->state=NR_ICE_COMPONENT_NOMINATED;
     comp->nominated=pair;
     comp->active=pair;
 
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/comp(%d): cancelling all pairs but %s (0x%p)",comp->stream->pctx->label,comp->stream->label,comp->component_id,pair->as_string,pair);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/COMP(%d)/CAND-PAIR(%s): cancelling all pairs but %s",comp->stream->pctx->label,comp->stream->label,comp->component_id,pair->codeword,pair->as_string);
 
     /* Cancel checks in WAITING and FROZEN per ICE S 8.1.2 */
     p2=TAILQ_FIRST(&comp->stream->check_list);
     while(p2){
       if((p2 != pair) &&
          (p2->remote->component->component_id == comp->component_id) &&
          ((p2->state == NR_ICE_PAIR_STATE_FROZEN) ||
 	  (p2->state == NR_ICE_PAIR_STATE_WAITING))) {
-        r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/comp(%d): cancelling pair %s (0x%p)",comp->stream->pctx->label,comp->stream->label,comp->component_id,p2->as_string,p2);
+        r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/COMP(%d)/CAND-PAIR(%s): cancelling FROZEN/WAITING pair %s because CAND-PAIR(%s) was nominated.",comp->stream->pctx->label,comp->stream->label,comp->component_id,p2->codeword,p2->as_string,pair->codeword);
 
         if(r=nr_ice_candidate_pair_cancel(pair->pctx,p2))
           ABORT(r);
       }
 
       p2=TAILQ_NEXT(p2,entry);
     }
-    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/comp(%d): cancelling done",comp->stream->pctx->label,comp->stream->label,comp->component_id);
+    r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/STREAM(%s)/COMP(%d): cancelling done",comp->stream->pctx->label,comp->stream->label,comp->component_id);
 
     if(r=nr_ice_media_stream_component_nominated(comp->stream,comp))
       ABORT(r);
 
     _status=0;
   abort:
     return(_status);
   }
--- a/media/mtransport/third_party/nICEr/src/stun/stun_client_ctx.c
+++ b/media/mtransport/third_party/nICEr/src/stun/stun_client_ctx.c
@@ -280,17 +280,17 @@ int nr_stun_client_force_retransmit(nr_s
 static int nr_stun_client_send_request(nr_stun_client_ctx *ctx)
   {
     int r,_status;
     char string[256];
 
     if (ctx->state != NR_STUN_CLIENT_STATE_RUNNING)
         ABORT(R_NOT_PERMITTED);
 
-    r_log(NR_LOG_STUN,LOG_DEBUG,"STUN-CLIENT(%s): Sending(my_addr=%s,peer_addr=%s)",ctx->label,ctx->my_addr.as_string,ctx->peer_addr.as_string);
+    r_log(NR_LOG_STUN,LOG_DEBUG,"STUN-CLIENT(%s): Sending check request (my_addr=%s,peer_addr=%s)",ctx->label,ctx->my_addr.as_string,ctx->peer_addr.as_string);
 
     if (ctx->request == 0) {
         switch (ctx->mode) {
         case NR_STUN_CLIENT_MODE_BINDING_REQUEST_LONG_TERM_AUTH:
             ctx->params.stun_binding_request.nonce = ctx->nonce;
             ctx->params.stun_binding_request.realm = ctx->realm;
             assert(0);
             ABORT(R_INTERNAL);
@@ -430,17 +430,17 @@ int nr_stun_client_process_response(nr_s
 
     ATTACH_DATA(hmac_key, hmac_key_d);
 
     if(ctx->state==NR_STUN_CLIENT_STATE_CANCELLED)
       ABORT(R_REJECTED);
     if (ctx->state != NR_STUN_CLIENT_STATE_RUNNING)
       ABORT(R_REJECTED);
 
-    r_log(NR_LOG_STUN,LOG_DEBUG,"STUN-CLIENT(%s): Received(my_addr=%s,peer_addr=%s)",ctx->label,ctx->my_addr.as_string,peer_addr->as_string);
+    r_log(NR_LOG_STUN,LOG_DEBUG,"STUN-CLIENT(%s): Received check response (my_addr=%s,peer_addr=%s)",ctx->label,ctx->my_addr.as_string,peer_addr->as_string);
 
     snprintf(string, sizeof(string)-1, "STUN-CLIENT(%s): Received ", ctx->label);
     r_dump(NR_LOG_STUN, LOG_DEBUG, string, (char*)msg, len);
 
     /* determine password */
     switch (ctx->mode) {
     case NR_STUN_CLIENT_MODE_BINDING_REQUEST_LONG_TERM_AUTH:
       compute_lt_key = 1;
@@ -513,29 +513,29 @@ int nr_stun_client_process_response(nr_s
       }
       password = &hmac_key;
     }
 
     if ((r=nr_stun_message_create2(&ctx->response, msg, len)))
         ABORT(r);
 
     if ((r=nr_stun_decode_message(ctx->response, nr_stun_client_get_password, password))) {
-        r_log(NR_LOG_STUN,LOG_DEBUG,"STUN-CLIENT(%s): error decoding message",ctx->label);
+        r_log(NR_LOG_STUN,LOG_DEBUG,"STUN-CLIENT(%s): error decoding response",ctx->label);
         ABORT(r);
     }
 
     /* This will return an error if request and response don't match,
        which is how we reject responses that match other contexts. */
     if ((r=nr_stun_receive_message(ctx->request, ctx->response))) {
-        r_log(NR_LOG_STUN,LOG_DEBUG,"STUN-CLIENT(%s): error receiving message",ctx->label);
+        r_log(NR_LOG_STUN,LOG_DEBUG,"STUN-CLIENT(%s): error receiving response",ctx->label);
         ABORT(r);
     }
 
     r_log(NR_LOG_STUN,LOG_DEBUG,
-          "STUN-CLIENT(%s): successfully received message; processing",ctx->label);
+          "STUN-CLIENT(%s): successfully received response; processing",ctx->label);
 
 /* TODO: !nn! currently using password!=0 to mean that auth is required,
  * TODO: !nn! but we should probably pass that in explicitly via the
  * TODO: !nn! usage (ctx->mode?) */
     if (password) {
         if (nr_stun_message_has_attribute(ctx->response, NR_STUN_ATTR_NONCE, 0)) {
             if ((r=nr_stun_receive_response_long_term_auth(ctx->response, ctx)))
                 ABORT(r);