Trace log inbound messages (#641)

* Trace log inbound messages

On an ICE restart in controlled mode, seeing incoming messages
getting discarded to due to username mismatch. That is because the
broswer is still using its old candidate and user name. As the
controlled agent waits for `useCandidate` from the controlling agent,
the controlled agent does not get to connected/nominated state inspite
of getting several success responses. Suspect the controlling side does
not have `useCandidate` for the new pair and it is still sending it for
the old pair. Logging more details in trace to understand it better.

* Fix test

agent.go

@@ -1096,6 +1096,8 @@ func (a *Agent) handleInbound(m *stun.Message, local Candidate, remote net.Addr)
 
 		a.selector.HandleSuccessResponse(m, local, remoteCandidate, remote)
 	} else if m.Type.Class == stun.ClassRequest {
+		a.log.Tracef("Inbound STUN (Request) from %s to %s, useCandidate: %v", remote.String(), local.String(), m.Contains(stun.AttrUseCandidate))
+
 		if err = stunx.AssertUsername(m, a.localUfrag+":"+a.remoteUfrag); err != nil {
 			a.log.Warnf("Discard message from (%s), %v", remote, err)
 			return
@@ -1131,8 +1133,6 @@ func (a *Agent) handleInbound(m *stun.Message, local Candidate, remote net.Addr)
 			a.addRemoteCandidate(remoteCandidate)
 		}
 
-		a.log.Tracef("Inbound STUN (Request) from %s to %s", remote.String(), local.String())
-
 		a.selector.HandleBindingRequest(m, local, remoteCandidate)
 	}
 

agent_get_best_valid_candidate_pair_test.go

@@ -23,7 +23,7 @@ func TestAgentGetBestValidCandidatePair(t *testing.T) {
 		candidatePair.state = CandidatePairStateSucceeded
 
 		actualBestPair := f.sut.getBestValidCandidatePair()
-		expectedBestPair := &CandidatePair{Remote: remoteCandidate, Local: f.hostLocal}
+		expectedBestPair := &CandidatePair{Remote: remoteCandidate, Local: f.hostLocal, state: CandidatePairStateSucceeded}
 
 		require.Equal(t, actualBestPair.String(), expectedBestPair.String())
 	}

candidatepair.go

@@ -35,8 +35,8 @@ func (p *CandidatePair) String() string {
 		return ""
 	}
 
-	return fmt.Sprintf("prio %d (local, prio %d) %s <-> %s (remote, prio %d)",
-		p.priority(), p.Local.Priority(), p.Local, p.Remote, p.Remote.Priority())
+	return fmt.Sprintf("prio %d (local, prio %d) %s <-> %s (remote, prio %d), state: %s, nominated: %v, nominateOnBindingSuccess: %v",
+		p.priority(), p.Local.Priority(), p.Local, p.Remote, p.Remote.Priority(), p.state, p.nominated, p.nominateOnBindingSuccess)
 }
 
 func (p *CandidatePair) equal(other *CandidatePair) bool {