Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 6bd0290d authored by Ken Chen's avatar Ken Chen
Browse files

Enable some DNS logs in userdebug build 

1. Set DNS default logging level to INFO.
2. Adjust logging level on some traces.

Output:
[Success]
resolv  : GetAddrInfoHandler::run: {100 983140 100 983140 1021 0}
resolv  : res_nmkquery: (QUERY, IN, A)
resolv  : res_nsend: used send_dg 97 terrno: 0
resolv  : doQuery: rcode=0, ancount=4

[Cache hit]
resolv  : GetAddrInfoHandler::run: {100 786532 100 983140 0 0}
resolv  : res_nmkquery: (QUERY, IN, AAAA)
resolv  : resolv_cache_lookup: FOUND IN CACHE entry=0xb4000075f51973d0
resolv  : doQuery: rcode=0, ancount=1

[Error - NXDOMAIN]
resolv  : GetAddrInfoHandler::run: {100 786532 100 983140 0 0}
resolv  : res_nmkquery: (QUERY, IN, AAAA)
resolv  : res_nsend: used send_dg 104 terrno: 0
resolv  : doQuery: rcode=3, ancount=0

[Timeout]
resolv  : GetAddrInfoHandler::run: {30 983070 30 983070 0 0}
resolv  : res_nmkquery: (QUERY, IN, A)
resolv  : res_nsend: used send_dg 0 terrno: 110
resolv  : res_nsend: used send_dg 0 terrno: 110
resolv  : doQuery: rcode=255, ancount=0
...

Bug: N/A
Test: m; adb logcat
Change-Id: I2a0ea2b416264d59382ef121d6d7755f8c7ffdf7
parent 0f163df8

DnsProxyListener.cpp

+6 −6
Original line number Diff line number Diff line
@@ -727,9 +727,9 @@ void DnsProxyListener::GetAddrInfoHandler::doDns64Synthesis(int32_t* rv, addrinf 
}



void DnsProxyListener::GetAddrInfoHandler::run() {

    LOG(DEBUG) << "GetAddrInfoHandler::run: {" << mNetContext.app_netid << " "

               << mNetContext.app_mark << " " << mNetContext.dns_netid << " "

               << mNetContext.dns_mark << " " << mNetContext.uid << " " << mNetContext.flags << "}";

    LOG(INFO) << "GetAddrInfoHandler::run: {" << mNetContext.app_netid << " "

              << mNetContext.app_mark << " " << mNetContext.dns_netid << " " << mNetContext.dns_mark

              << " " << mNetContext.uid << " " << mNetContext.flags << "}";



    addrinfo* result = nullptr;

    Stopwatch s;
@@ -902,9 +902,9 @@ DnsProxyListener::ResNSendHandler::ResNSendHandler(SocketClient* c, std::string 
    : Handler(c), mMsg(std::move(msg)), mFlags(flags), mNetContext(netcontext) {}



void DnsProxyListener::ResNSendHandler::run() {

    LOG(DEBUG) << "ResNSendHandler::run: " << mFlags << " / {" << mNetContext.app_netid << " "

               << mNetContext.app_mark << " " << mNetContext.dns_netid << " "

               << mNetContext.dns_mark << " " << mNetContext.uid << " " << mNetContext.flags << "}";

    LOG(INFO) << "ResNSendHandler::run: " << mFlags << " / {" << mNetContext.app_netid << " "

              << mNetContext.app_mark << " " << mNetContext.dns_netid << " " << mNetContext.dns_mark

              << " " << mNetContext.uid << " " << mNetContext.flags << "}";



    Stopwatch s;

    maybeFixupNetContext(&mNetContext, mClient->getPid());

DnsResolver.cpp

+3 −2
Original line number Diff line number Diff line
@@ -31,8 +31,9 @@ 
bool resolv_init(const ResolverNetdCallbacks* callbacks) {

    android::base::InitLogging(/*argv=*/nullptr);

    LOG(INFO) << __func__ << ": Initializing resolver";

    resolv_set_log_severity(android::base::WARNING);

    doh_init_logger(DOH_LOG_LEVEL_WARN);

    const bool isDebug = isUserDebugBuild();

    resolv_set_log_severity(isDebug ? android::base::INFO : android::base::WARNING);

    doh_init_logger(isDebug ? DOH_LOG_LEVEL_INFO : DOH_LOG_LEVEL_WARN);

    using android::net::gApiLevel;

    gApiLevel = getApiLevel();

    using android::net::gResNetdCallbacks;

getaddrinfo.cpp

+3 −3
Original line number Diff line number Diff line
@@ -1652,13 +1652,13 @@ QueryResult doQuery(const char* name, res_target* t, ResState* res, 
        if ((res_temp.netcontext_flags &

             (NET_CONTEXT_FLAG_USE_DNS_OVER_TLS | NET_CONTEXT_FLAG_USE_EDNS)) &&

            (res_temp.flags & RES_F_EDNS0ERR)) {

            LOG(DEBUG) << __func__ << ": retry without EDNS0";

            LOG(INFO) << __func__ << ": retry without EDNS0";

            n = res_nmkquery(QUERY, name, cl, type, {}, buf, res_temp.netcontext_flags);

            n = res_nsend(&res_temp, {buf, n}, {t->answer.data(), anslen}, &rcode, 0);

        }

    }



    LOG(DEBUG) << __func__ << ": rcode=" << rcode << ", ancount=" << ntohs(hp->ancount);

    LOG(INFO) << __func__ << ": rcode=" << rcode << ", ancount=" << ntohs(hp->ancount);



    t->n = n;

    return {
@@ -1780,7 +1780,7 @@ static int res_queryN(const char* name, res_target* target, ResState* res, int* 
                retried = true;

                goto again;

            }

            LOG(DEBUG) << __func__ << ": rcode=" << rcode << ", ancount=" << ntohs(hp->ancount);

            LOG(INFO) << __func__ << ": rcode=" << rcode << ", ancount=" << ntohs(hp->ancount);

            continue;

        }

res_cache.cpp

+13 −13
Original line number Diff line number Diff line
@@ -802,7 +802,7 @@ static uint32_t answer_getTTL(span<const uint8_t> answer) { 
        PLOG(INFO) << __func__ << ": ns_initparse failed";

    }



    LOG(INFO) << __func__ << ": TTL = " << result;

    LOG(DEBUG) << __func__ << ": TTL = " << result;

    return result;

}
@@ -1124,7 +1124,7 @@ static void cache_dump_mru_locked(Cache* cache) { 
        fmt::format_to(std::back_inserter(buf), " {}", e->id);

    }



    LOG(INFO) << __func__ << ": " << buf;

    LOG(DEBUG) << __func__ << ": " << buf;

}



/* This function tries to find a key within the hash table
@@ -1168,7 +1168,7 @@ static void _cache_add_p(Cache* cache, Entry** lookup, Entry* e) { 
    entry_mru_add(e, &cache->mru_list);

    cache->num_entries += 1;



    LOG(INFO) << __func__ << ": entry " << e->id << " added (count=" << cache->num_entries << ")";

    LOG(DEBUG) << __func__ << ": entry " << e->id << " added (count=" << cache->num_entries << ")";

}



/* Remove an existing entry from the hash table,
@@ -1178,7 +1178,7 @@ static void _cache_add_p(Cache* cache, Entry** lookup, Entry* e) { 
static void _cache_remove_p(Cache* cache, Entry** lookup) {

    Entry* e = *lookup;



    LOG(INFO) << __func__ << ": entry " << e->id << " removed (count=" << cache->num_entries - 1

    LOG(DEBUG) << __func__ << ": entry " << e->id << " removed (count=" << cache->num_entries - 1

               << ")";



    entry_mru_remove(e);
@@ -1197,7 +1197,7 @@ static void _cache_remove_oldest(Cache* cache) { 
        LOG(INFO) << __func__ << ": OLDEST NOT IN HTABLE ?";

        return;

    }

    LOG(INFO) << __func__ << ": Cache full - removing oldest";

    LOG(DEBUG) << __func__ << ": Cache full - removing oldest";

    res_pquery({oldest->query, oldest->querylen});

    _cache_remove_p(cache, lookup);

}
@@ -1243,7 +1243,7 @@ ResolvCacheStatus resolv_cache_lookup(unsigned netid, span<const uint8_t> query, 
    Entry* e;

    time_t now;



    LOG(INFO) << __func__ << ": lookup";

    LOG(DEBUG) << __func__ << ": lookup";



    /* we don't cache malformed queries */

    if (!entry_init_key(&key, query)) {
@@ -1265,7 +1265,7 @@ ResolvCacheStatus resolv_cache_lookup(unsigned netid, span<const uint8_t> query, 
    e = *lookup;



    if (e == NULL) {

        LOG(INFO) << __func__ << ": NOT IN CACHE";

        LOG(DEBUG) << __func__ << ": NOT IN CACHE";



        if (!cache_has_pending_request_locked(cache, &key, true)) {

            return RESOLV_CACHE_NOTFOUND;
@@ -1302,7 +1302,7 @@ ResolvCacheStatus resolv_cache_lookup(unsigned netid, span<const uint8_t> query, 


    /* remove stale entries here */

    if (now >= e->expires) {

        LOG(INFO) << __func__ << ": NOT IN CACHE (STALE ENTRY " << *lookup << "DISCARDED)";

        LOG(DEBUG) << __func__ << ": NOT IN CACHE (STALE ENTRY " << *lookup << "DISCARDED)";

        res_pquery({e->query, e->querylen});

        _cache_remove_p(cache, lookup);

        return RESOLV_CACHE_NOTFOUND;
@@ -1642,7 +1642,7 @@ int resolv_set_nameservers(unsigned netid, const std::vector<std::string>& serve 
    std::vector<std::string> nameservers = filter_nameservers(servers);

    const int numservers = static_cast<int>(nameservers.size());



    LOG(INFO) << __func__ << ": netId = " << netid << ", numservers = " << numservers;

    LOG(DEBUG) << __func__ << ": netId = " << netid << ", numservers = " << numservers;



    // Parse the addresses before actually locking or changing any state, in case there is an error.

    // As a side effect this also reduces the time the lock is kept.
@@ -1730,7 +1730,7 @@ void resolv_populate_res_for_net(ResState* statp) { 
    if (statp == nullptr) {

        return;

    }

    LOG(INFO) << __func__ << ": netid=" << statp->netid;

    LOG(DEBUG) << __func__ << ": netid=" << statp->netid;



    std::lock_guard guard(cache_mutex);

    NetConfig* info = find_netconfig_locked(statp->netid);
@@ -1751,7 +1751,7 @@ static void res_cache_add_stats_sample_locked(res_stats* stats, const res_sample 
                                              int max_samples) {

    // Note: This function expects max_samples > 0, otherwise a (harmless) modification of the

    // allocated but supposedly unused memory for samples[0] will happen

    LOG(INFO) << __func__ << ": adding sample to stats, next = " << unsigned(stats->sample_next)

    LOG(DEBUG) << __func__ << ": adding sample to stats, next = " << unsigned(stats->sample_next)

               << ", count = " << unsigned(stats->sample_count);

    stats->samples[stats->sample_next] = sample;

    if (stats->sample_count < max_samples) {

res_mkquery.cpp

+2 −2
Original line number Diff line number Diff line
@@ -108,7 +108,7 @@ int res_nmkquery(int op, // opcode of query 
    int n;

    uint8_t *dnptrs[20], **dpp, **lastdnptr;



    LOG(DEBUG) << __func__ << ": (" << _res_opcodes[op] << ", " << p_class(cl) << ", "

    LOG(INFO) << __func__ << ": (" << _res_opcodes[op] << ", " << p_class(cl) << ", "

              << p_type(type) << ")";



    /*