Bug 906990 - Part 11. Enable r_log and RLogRingBuffer so logging can be scraped. Also, tweak log levels so the RLogRingBuffer isn't rapidly overwritten by media packet logging. r=ekr

This commit is contained in:
Byron Campen [:bwc] 2013-10-24 11:47:16 -07:00
parent a9ae2734ef
commit a562097627
5 changed files with 68 additions and 66 deletions

View File

@ -83,6 +83,7 @@ extern "C" {
#include "nricemediastream.h"
#include "nr_socket_prsock.h"
#include "nrinterfaceprioritizer.h"
#include "rlogringbuffer.h"
namespace mozilla {
@ -336,9 +337,10 @@ RefPtr<NrIceCtx> NrIceCtx::Create(const std::string& name,
bool set_interface_priorities) {
RefPtr<NrIceCtx> ctx = new NrIceCtx(name, offerer);
// Initialize the crypto callbacks
// Initialize the crypto callbacks and logging stuff
if (!initialized) {
NR_reg_init(NR_REG_MODE_LOCAL);
RLogRingBuffer::CreateInstance();
nr_crypto_vtbl = &nr_ice_crypto_nss_vtbl;
initialized = true;

View File

@ -70,7 +70,7 @@ inline void RLogRingBuffer::RemoveOld() {
RLogRingBuffer* RLogRingBuffer::CreateInstance() {
if (!instance) {
instance = new RLogRingBuffer;
r_log_set_extra_destination(LOG_DEBUG, &ringbuffer_vlog);
r_log_set_extra_destination(LOG_INFO, &ringbuffer_vlog);
}
return instance;
}
@ -81,7 +81,7 @@ RLogRingBuffer* RLogRingBuffer::GetInstance() {
void RLogRingBuffer::DestroyInstance() {
// First param is ignored when passing null
r_log_set_extra_destination(LOG_DEBUG, nullptr);
r_log_set_extra_destination(LOG_INFO, nullptr);
delete instance;
instance = nullptr;
}

View File

@ -61,21 +61,21 @@ TEST_F(RLogRingBufferTest, TestFilterEmpty) {
}
TEST_F(RLogRingBufferTest, TestBasicFilter) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test");
r_log(NR_LOG_TEST, LOG_INFO, "Test");
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->Filter("Test", 0, &logs);
ASSERT_EQ(1U, logs.size());
}
TEST_F(RLogRingBufferTest, TestBasicFilterContent) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test");
r_log(NR_LOG_TEST, LOG_INFO, "Test");
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->Filter("Test", 0, &logs);
ASSERT_EQ("Test", logs.back());
}
TEST_F(RLogRingBufferTest, TestFilterAnyFrontMatch) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test");
r_log(NR_LOG_TEST, LOG_INFO, "Test");
std::vector<std::string> substrings;
substrings.push_back("foo");
substrings.push_back("Test");
@ -85,7 +85,7 @@ TEST_F(RLogRingBufferTest, TestFilterAnyFrontMatch) {
}
TEST_F(RLogRingBufferTest, TestFilterAnyBackMatch) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test");
r_log(NR_LOG_TEST, LOG_INFO, "Test");
std::vector<std::string> substrings;
substrings.push_back("Test");
substrings.push_back("foo");
@ -95,7 +95,7 @@ TEST_F(RLogRingBufferTest, TestFilterAnyBackMatch) {
}
TEST_F(RLogRingBufferTest, TestFilterAnyBothMatch) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test");
r_log(NR_LOG_TEST, LOG_INFO, "Test");
std::vector<std::string> substrings;
substrings.push_back("Tes");
substrings.push_back("est");
@ -105,7 +105,7 @@ TEST_F(RLogRingBufferTest, TestFilterAnyBothMatch) {
}
TEST_F(RLogRingBufferTest, TestFilterAnyNeitherMatch) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test");
r_log(NR_LOG_TEST, LOG_INFO, "Test");
std::vector<std::string> substrings;
substrings.push_back("tes");
substrings.push_back("esT");
@ -115,16 +115,16 @@ TEST_F(RLogRingBufferTest, TestFilterAnyNeitherMatch) {
}
TEST_F(RLogRingBufferTest, TestAllMatch) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->GetAny(0, &logs);
ASSERT_EQ(2U, logs.size());
}
TEST_F(RLogRingBufferTest, TestOrder) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->GetAny(0, &logs);
ASSERT_EQ("Test2", logs.back());
@ -132,16 +132,16 @@ TEST_F(RLogRingBufferTest, TestOrder) {
}
TEST_F(RLogRingBufferTest, TestNoMatch) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->Filter("foo", 0, &logs);
ASSERT_EQ(0U, logs.size());
}
TEST_F(RLogRingBufferTest, TestSubstringFilter) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->Filter("t1", 0, &logs);
ASSERT_EQ(1U, logs.size());
@ -149,12 +149,12 @@ TEST_F(RLogRingBufferTest, TestSubstringFilter) {
}
TEST_F(RLogRingBufferTest, TestFilterLimit) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test3");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test4");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test5");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test6");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test3");
r_log(NR_LOG_TEST, LOG_INFO, "Test4");
r_log(NR_LOG_TEST, LOG_INFO, "Test5");
r_log(NR_LOG_TEST, LOG_INFO, "Test6");
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->Filter("Test", 2, &logs);
ASSERT_EQ(2U, logs.size());
@ -163,12 +163,12 @@ TEST_F(RLogRingBufferTest, TestFilterLimit) {
}
TEST_F(RLogRingBufferTest, TestFilterAnyLimit) {
r_log(NR_LOG_TEST, LOG_DEBUG, "TestOne");
r_log(NR_LOG_TEST, LOG_DEBUG, "TestTwo");
r_log(NR_LOG_TEST, LOG_DEBUG, "TestThree");
r_log(NR_LOG_TEST, LOG_DEBUG, "TestFour");
r_log(NR_LOG_TEST, LOG_DEBUG, "TestFive");
r_log(NR_LOG_TEST, LOG_DEBUG, "TestSix");
r_log(NR_LOG_TEST, LOG_INFO, "TestOne");
r_log(NR_LOG_TEST, LOG_INFO, "TestTwo");
r_log(NR_LOG_TEST, LOG_INFO, "TestThree");
r_log(NR_LOG_TEST, LOG_INFO, "TestFour");
r_log(NR_LOG_TEST, LOG_INFO, "TestFive");
r_log(NR_LOG_TEST, LOG_INFO, "TestSix");
std::vector<std::string> substrings;
// Matches Two, Three, Four, and Six
substrings.push_back("tT");
@ -184,12 +184,12 @@ TEST_F(RLogRingBufferTest, TestFilterAnyLimit) {
TEST_F(RLogRingBufferTest, TestLimit) {
RLogRingBuffer::GetInstance()->SetLogLimit(3);
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test3");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test4");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test5");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test6");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test3");
r_log(NR_LOG_TEST, LOG_INFO, "Test4");
r_log(NR_LOG_TEST, LOG_INFO, "Test5");
r_log(NR_LOG_TEST, LOG_INFO, "Test6");
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->GetAny(0, &logs);
ASSERT_EQ(3U, logs.size());
@ -198,12 +198,12 @@ TEST_F(RLogRingBufferTest, TestLimit) {
}
TEST_F(RLogRingBufferTest, TestLimitBulkDiscard) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test3");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test4");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test5");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test6");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test3");
r_log(NR_LOG_TEST, LOG_INFO, "Test4");
r_log(NR_LOG_TEST, LOG_INFO, "Test5");
r_log(NR_LOG_TEST, LOG_INFO, "Test6");
RLogRingBuffer::GetInstance()->SetLogLimit(3);
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->GetAny(0, &logs);
@ -214,12 +214,12 @@ TEST_F(RLogRingBufferTest, TestLimitBulkDiscard) {
TEST_F(RLogRingBufferTest, TestIncreaseLimit) {
RLogRingBuffer::GetInstance()->SetLogLimit(3);
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test3");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test4");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test5");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test6");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test3");
r_log(NR_LOG_TEST, LOG_INFO, "Test4");
r_log(NR_LOG_TEST, LOG_INFO, "Test5");
r_log(NR_LOG_TEST, LOG_INFO, "Test6");
RLogRingBuffer::GetInstance()->SetLogLimit(300);
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->GetAny(0, &logs);
@ -229,12 +229,12 @@ TEST_F(RLogRingBufferTest, TestIncreaseLimit) {
}
TEST_F(RLogRingBufferTest, TestClear) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test3");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test4");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test5");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test6");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test3");
r_log(NR_LOG_TEST, LOG_INFO, "Test4");
r_log(NR_LOG_TEST, LOG_INFO, "Test5");
r_log(NR_LOG_TEST, LOG_INFO, "Test6");
RLogRingBuffer::GetInstance()->SetLogLimit(0);
RLogRingBuffer::GetInstance()->SetLogLimit(4096);
std::deque<std::string> logs;
@ -243,12 +243,12 @@ TEST_F(RLogRingBufferTest, TestClear) {
}
TEST_F(RLogRingBufferTest, TestReInit) {
r_log(NR_LOG_TEST, LOG_DEBUG, "Test1");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test2");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test3");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test4");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test5");
r_log(NR_LOG_TEST, LOG_DEBUG, "Test6");
r_log(NR_LOG_TEST, LOG_INFO, "Test1");
r_log(NR_LOG_TEST, LOG_INFO, "Test2");
r_log(NR_LOG_TEST, LOG_INFO, "Test3");
r_log(NR_LOG_TEST, LOG_INFO, "Test4");
r_log(NR_LOG_TEST, LOG_INFO, "Test5");
r_log(NR_LOG_TEST, LOG_INFO, "Test6");
ReInit();
std::deque<std::string> logs;
RLogRingBuffer::GetInstance()->GetAny(0, &logs);

View File

@ -383,7 +383,7 @@ int nr_ice_candidate_pair_do_triggered_check(nr_ice_peer_ctx *pctx, nr_ice_cand_
{
int r,_status;
r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/CAND-PAIR(%s): triggered check on %s",pctx->label,pair->codeword,pair->as_string);
r_log(LOG_ICE,LOG_INFO,"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:
@ -461,7 +461,7 @@ int nr_ice_candidate_pair_set_state(nr_ice_peer_ctx *pctx, nr_ice_cand_pair *pai
{
int r,_status;
r_log(LOG_ICE,LOG_DEBUG,"ICE-PEER(%s)/CAND-PAIR(%s): setting pair to state %s: %s",
r_log(LOG_ICE,LOG_INFO,"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
@ -533,7 +533,7 @@ void nr_ice_candidate_pair_restart_stun_nominated_cb(NR_SOCKET s, int how, void
pair->restart_nominated_cb_timer=0;
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);
r_log(LOG_ICE,LOG_INFO,"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);
@ -555,7 +555,7 @@ static void nr_ice_candidate_pair_restart_stun_controlled_cb(NR_SOCKET s, int ho
pair->restart_controlled_cb_timer=0;
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);
r_log(LOG_ICE,LOG_INFO,"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;

View File

@ -792,7 +792,7 @@ int nr_ice_component_nominated_pair(nr_ice_component *comp, nr_ice_cand_pair *pa
if(comp->nominated){
if(comp->nominated->priority > pair->priority)
return(0);
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);
r_log(LOG_ICE,LOG_INFO,"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 */
@ -801,7 +801,7 @@ int nr_ice_component_nominated_pair(nr_ice_component *comp, nr_ice_cand_pair *pa
comp->nominated=pair;
comp->active=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);
r_log(LOG_ICE,LOG_INFO,"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);
@ -810,7 +810,7 @@ int nr_ice_component_nominated_pair(nr_ice_component *comp, nr_ice_cand_pair *pa
(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)/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);
r_log(LOG_ICE,LOG_INFO,"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);