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

Commit 3952ccca authored by Bernie Innocenti's avatar Bernie Innocenti
Browse files

resolv: small improvements for debug logging 

 - use __func__ instead of the hand-written and often incorrect names
 - fix a few cosmetic issues, such as those ugly ";;" prefixes
 - add some logging around explore_fqdn and explore_numeric
 - change the verbosity of a few messages
 - replace compile-time DBG macro with verbosity checks in DnsProxyListener
 - delete various unused functions in res_debug
 - skip slow res_pquery() if log level is less than VERBOSE

TODO: convert the remaining ALOGx() lines to LOG(x). Leaving this for a
future patch.

Test: as follows:
    adb shell setprop persist.sys.nw_dns_resolver_log DEBUG
    atest reolv_integration_test

Change-Id: I7153f0c75d39d513fa006e0c1e5bf649d47ba154
parent 253ea334

DnsProxyListener.cpp

+29 −47
Original line number Diff line number Diff line
@@ -28,8 +28,6 @@ 
#include <sys/types.h>



#define LOG_TAG "DnsProxyListener"

#define DBG 0

#define VDBG 0



#include <algorithm>

#include <list>
@@ -103,6 +101,7 @@ constexpr int MAXPACKET = 8 * 1024; 
android::netdutils::OperationLimiter<uid_t> queryLimiter(MAX_QUERIES_PER_UID);



void logArguments(int argc, char** argv) {

    if (!WOULD_LOG(DEBUG)) return;

    for (int i = 0; i < argc; i++) {

        ALOGD("argv[%i]=%s", i, argv[i]);

    }
@@ -374,6 +373,7 @@ bool onlyNonSpecialUseIPv4Addresses(const addrinfo* res) { 
}



void logDnsQueryResult(const struct hostent* hp) {

    if (!WOULD_LOG(DEBUG)) return;

    if (hp == nullptr) return;



    ALOGD("DNS records:");
@@ -389,6 +389,7 @@ void logDnsQueryResult(const struct hostent* hp) { 
}



void logDnsQueryResult(const addrinfo* res) {

    if (!WOULD_LOG(DEBUG)) return;

    if (res == nullptr) return;



    int i;
@@ -439,7 +440,7 @@ bool synthesizeNat64PrefixWithARecord(const netdutils::IPPrefix& prefix, struct 
        *ia6 = v6prefix->sin6_addr;

        ia6->s6_addr32[3] = iaOriginal.s_addr;



        if (DBG) {

        if (WOULD_LOG(DEBUG)) {

            char buf[INET6_ADDRSTRLEN];  // big enough for either IPv4 or IPv6

            inet_ntop(AF_INET, &iaOriginal.s_addr, buf, sizeof(buf));

            ALOGD("DNS A record: %s", buf);
@@ -452,7 +453,7 @@ bool synthesizeNat64PrefixWithARecord(const netdutils::IPPrefix& prefix, struct 
    hp->h_addrtype = AF_INET6;

    hp->h_length = sizeof(in6_addr);



    if (DBG) logDnsQueryResult(hp);

    logDnsQueryResult(hp);

    return true;

}
@@ -477,7 +478,7 @@ bool synthesizeNat64PrefixWithARecord(const netdutils::IPPrefix& prefix, addrinf 
        ai->ai_addrlen = sizeof(struct sockaddr_in6);

        ai->ai_family = AF_INET6;



        if (DBG) {

        if (WOULD_LOG(DEBUG)) {

            char buf[INET6_ADDRSTRLEN];  // big enough for either IPv4 or IPv6

            inet_ntop(AF_INET, &sinOriginal.sin_addr.s_addr, buf, sizeof(buf));

            ALOGD("DNS A record: %s", buf);
@@ -487,7 +488,7 @@ bool synthesizeNat64PrefixWithARecord(const netdutils::IPPrefix& prefix, addrinf 
            ALOGD("DNS64 Synthesized AAAA record: %s", buf);

        }

    }

    if (DBG) logDnsQueryResult(result);

    logDnsQueryResult(result);

    return true;

}
@@ -652,12 +653,9 @@ void DnsProxyListener::GetAddrInfoHandler::doDns64Synthesis(int32_t* rv, addrinf 
}



void DnsProxyListener::GetAddrInfoHandler::run() {

    if (DBG) {

    ALOGD("GetAddrInfoHandler, now for %s / %s / {%u,%u,%u,%u,%u,%u}", mHost, mService,

                mNetContext.app_netid, mNetContext.app_mark,

                mNetContext.dns_netid, mNetContext.dns_mark,

          mNetContext.app_netid, mNetContext.app_mark, mNetContext.dns_netid, mNetContext.dns_mark,

          mNetContext.uid, mNetContext.flags);

    }



    addrinfo* result = nullptr;

    Stopwatch s;
@@ -721,7 +719,7 @@ DnsProxyListener::GetAddrInfoCmd::GetAddrInfoCmd() : FrameworkCommand("getaddrin 


int DnsProxyListener::GetAddrInfoCmd::runCommand(SocketClient *cli,

                                            int argc, char **argv) {

    if (DBG) logArguments(argc, argv);

    logArguments(argc, argv);



    if (argc != 8) {

        char* msg = nullptr;
@@ -771,14 +769,9 @@ int DnsProxyListener::GetAddrInfoCmd::runCommand(SocketClient *cli, 
        hints->ai_protocol = ai_protocol;

    }



    if (DBG) {

        ALOGD("GetAddrInfoHandler for %s / %s / {%u,%u,%u,%u,%u}",

             name ? name : "[nullhost]",

             service ? service : "[nullservice]",

             netcontext.app_netid, netcontext.app_mark,

             netcontext.dns_netid, netcontext.dns_mark,

             netcontext.uid);

    }

    ALOGD("GetAddrInfoHandler for %s / %s / {%u,%u,%u,%u,%u}", name ? name : "[nullhost]",

          service ? service : "[nullservice]", netcontext.app_netid, netcontext.app_mark,

          netcontext.dns_netid, netcontext.dns_mark, netcontext.uid);



    DnsProxyListener::GetAddrInfoHandler* handler =

            new DnsProxyListener::GetAddrInfoHandler(cli, name, service, hints, netcontext);
@@ -792,7 +785,7 @@ int DnsProxyListener::GetAddrInfoCmd::runCommand(SocketClient *cli, 
DnsProxyListener::ResNSendCommand::ResNSendCommand() : FrameworkCommand("resnsend") {}



int DnsProxyListener::ResNSendCommand::runCommand(SocketClient* cli, int argc, char** argv) {

    if (DBG) logArguments(argc, argv);

    logArguments(argc, argv);



    const uid_t uid = cli->getUid();

    if (argc != 4) {
@@ -836,11 +829,9 @@ DnsProxyListener::ResNSendHandler::~ResNSendHandler() { 
}



void DnsProxyListener::ResNSendHandler::run() {

    if (DBG) {

    ALOGD("ResNSendHandler, now for %s %u/ {%u,%u,%u,%u,%u,%u}", mMsg.c_str(), mFlags,

              mNetContext.app_netid, mNetContext.app_mark, mNetContext.dns_netid,

              mNetContext.dns_mark, mNetContext.uid, mNetContext.flags);

    }

          mNetContext.app_netid, mNetContext.app_mark, mNetContext.dns_netid, mNetContext.dns_mark,

          mNetContext.uid, mNetContext.flags);



    Stopwatch s;

    maybeFixupNetContext(&mNetContext);
@@ -921,7 +912,7 @@ DnsProxyListener::GetHostByNameCmd::GetHostByNameCmd() : FrameworkCommand("getho 


int DnsProxyListener::GetHostByNameCmd::runCommand(SocketClient *cli,

                                            int argc, char **argv) {

    if (DBG) logArguments(argc, argv);

    logArguments(argc, argv);



    if (argc != 4) {

        char* msg = nullptr;
@@ -1001,9 +992,7 @@ void DnsProxyListener::GetHostByNameHandler::doDns64Synthesis(int32_t* rv, struc 
}



void DnsProxyListener::GetHostByNameHandler::run() {

    if (DBG) {

    ALOGD("DnsProxyListener::GetHostByNameHandler::run");

    }



    Stopwatch s;

    maybeFixupNetContext(&mNetContext);
@@ -1021,12 +1010,9 @@ void DnsProxyListener::GetHostByNameHandler::run() { 
    doDns64Synthesis(&rv, &hp);

    const int latencyUs = lround(s.timeTakenUs());



    if (DBG) {

    ALOGD("GetHostByNameHandler::run gethostbyname errno: %s hp->h_name = %s, name_len = %zu",

                hp ? "success" : strerror(errno),

                (hp && hp->h_name) ? hp->h_name : "null",

          hp ? "success" : strerror(errno), (hp && hp->h_name) ? hp->h_name : "null",

          (hp && hp->h_name) ? strlen(hp->h_name) + 1 : 0);

    }



    bool success = true;

    if (hp) {
@@ -1056,7 +1042,7 @@ DnsProxyListener::GetHostByAddrCmd::GetHostByAddrCmd() : FrameworkCommand("getho 


int DnsProxyListener::GetHostByAddrCmd::runCommand(SocketClient *cli,

                                            int argc, char **argv) {

    if (DBG) logArguments(argc, argv);

    logArguments(argc, argv);



    if (argc != 5) {

        char* msg = nullptr;
@@ -1158,9 +1144,7 @@ void DnsProxyListener::GetHostByAddrHandler::doDns64ReverseLookup(struct hostent 
}



void DnsProxyListener::GetHostByAddrHandler::run() {

    if (DBG) {

    ALOGD("DnsProxyListener::GetHostByAddrHandler::run");

    }



    Stopwatch s;

    maybeFixupNetContext(&mNetContext);
@@ -1179,11 +1163,9 @@ void DnsProxyListener::GetHostByAddrHandler::run() { 
    doDns64ReverseLookup(&hp);

    const int latencyUs = int(s.timeTakenUs());



    if (DBG) {

    ALOGD("GetHostByAddrHandler::run gethostbyaddr result: %s hp->h_name = %s, name_len = %zu",

          hp ? "success" : gai_strerror(rv), (hp && hp->h_name) ? hp->h_name : "null",

          (hp && hp->h_name) ? strlen(hp->h_name) + 1 : 0);

    }



    bool success = true;

    if (hp) {

getaddrinfo.cpp

+14 −11
Original line number Diff line number Diff line
@@ -30,6 +30,8 @@ 
 * SUCH DAMAGE.

 */



#define LOG_TAG "getaddrinfo"



#include <arpa/inet.h>

#include <arpa/nameser.h>

#include <assert.h>
@@ -359,6 +361,8 @@ int android_getaddrinfofornetcontext(const char* hostname, const char* servname, 
            if (tmp.ai_socktype == ANY && ex.e_socktype != ANY) tmp.ai_socktype = ex.e_socktype;

            if (tmp.ai_protocol == ANY && ex.e_protocol != ANY) tmp.ai_protocol = ex.e_protocol;



            LOG(DEBUG) << "explore_numeric: ai_family=" << tmp.ai_family

                       << " ai_socktype=" << tmp.ai_socktype << " ai_protocol=" << tmp.ai_protocol;

            if (hostname == nullptr)

                error = explore_null(&tmp, servname, &cur->ai_next);

            else
@@ -405,6 +409,8 @@ int android_getaddrinfofornetcontext(const char* hostname, const char* servname, 
            if (tmp.ai_socktype == ANY && ex.e_socktype != ANY) tmp.ai_socktype = ex.e_socktype;

            if (tmp.ai_protocol == ANY && ex.e_protocol != ANY) tmp.ai_protocol = ex.e_protocol;



            LOG(DEBUG) << "explore_fqdn(): ai_family=" << tmp.ai_family

                       << " ai_socktype=" << tmp.ai_socktype << " ai_protocol=" << tmp.ai_protocol;

            error = explore_fqdn(&tmp, hostname, servname, &cur->ai_next, netcontext);



            while (cur->ai_next) cur = cur->ai_next;
@@ -1606,13 +1612,13 @@ static int res_queryN(const char* name, res_target* target, res_state res, int* 
        answer = t->answer;

        anslen = t->anslen;



        LOG(DEBUG) << ";; res_queryN(" << name << ", " << cl << " , " << type << ")";

        LOG(DEBUG) << __func__ << "(" << name << ", " << cl << ", " << type << ")";



        n = res_nmkquery(res, QUERY, name, cl, type, NULL, 0, NULL, buf, sizeof(buf));

        if (n > 0 && (res->options & (RES_USE_EDNS0 | RES_USE_DNSSEC)) != 0 && !retried)

            n = res_nopt(res, n, buf, sizeof(buf), anslen);

        if (n <= 0) {

            LOG(DEBUG) << ";; res_queryN: mkquery failed";

            LOG(ERROR) << __func__ << ": res_nmkquery failed";

            *herrno = NO_RECOVERY;

            return n;

        }
@@ -1625,11 +1631,11 @@ static int res_queryN(const char* name, res_target* target, res_state res, int* 
            /* if the query choked with EDNS0, retry without EDNS0 */

            if ((res->options & (RES_USE_EDNS0 | RES_USE_DNSSEC)) != 0 &&

                (res->_flags & RES_F_EDNS0ERR) && !retried) {

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

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

                retried = true;

                goto again;

            }

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

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

            continue;

        }
@@ -1806,13 +1812,11 @@ static int res_querydomainN(const char* name, const char* domain, res_target* ta 
    size_t n, d;



    assert(name != NULL);

    /* XXX: target may be NULL??? */



    LOG(DEBUG) << __func__ << "(\"" << name << "\", " << (domain ? domain : "<null>") << ")";



    if (domain == NULL) {

        LOG(DEBUG) << ";; res_querydomain(" << name << ", <Nil>)";

        /*

         * Check for trailing '.';

         * copy without '.' if present.

         */

        // Check for trailing '.'; copy without '.' if present.

        n = strlen(name);

        if (n + 1 > sizeof(nbuf)) {

            *herrno = NO_RECOVERY;
@@ -1824,7 +1828,6 @@ static int res_querydomainN(const char* name, const char* domain, res_target* ta 
        } else

            longname = name;

    } else {

        LOG(DEBUG) << ";; res_querydomain(" << name << ", " << domain << ")";

        n = strlen(name);

        d = strlen(domain);

        if (n + 1 + d + 1 > sizeof(nbuf)) {

res_cache.cpp

+8 −7
Original line number Diff line number Diff line
@@ -26,9 +26,6 @@ 
 * SUCH DAMAGE.

 */



// NOTE: verbose logging MUST NOT be left enabled in production binaries.

// It floods logs at high rate, and can leak privacy-sensitive information.

constexpr bool kDumpData = false;

#define LOG_TAG "res_cache"



#include "resolv_cache.h"
@@ -55,6 +52,10 @@ constexpr bool kDumpData = false; 
#include "res_state_ext.h"

#include "resolv_private.h"



// NOTE: verbose logging MUST NOT be left enabled in production binaries.

// It floods logs at high rate, and can leak privacy-sensitive information.

constexpr bool kDumpData = false;



/* This code implements a small and *simple* DNS resolver cache.

 *

 * It is only used to cache DNS answers for a time defined by the smallest TTL
@@ -1689,7 +1690,7 @@ int resolv_set_nameservers_for_net(unsigned netid, const char** servers, const i 
    struct addrinfo* nsaddrinfo[MAXNS];



    if (numservers > MAXNS) {

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

        LOG(ERROR) << __func__ << ": numservers=" << numservers << ", MAXNS=" << MAXNS;

        return E2BIG;

    }
@@ -1761,11 +1762,11 @@ int resolv_set_nameservers_for_net(unsigned netid, const char** servers, const i 


        // Always update the search paths, since determining whether they actually changed is

        // complex due to the zero-padding, and probably not worth the effort. Cache-flushing

        // however is not // necessary, since the stored cache entries do contain the domain, not

        // however is not necessary, since the stored cache entries do contain the domain, not

        // just the host name.

        // code moved from res_init.c, load_domain_search_list

        strlcpy(cache_info->defdname, domains, sizeof(cache_info->defdname));

        if ((cp = strchr(cache_info->defdname, '\n')) != NULL) *cp = '\0';

        LOG(INFO) << __func__ << ": domains=\"" << cache_info->defdname << "\"";



        cp = cache_info->defdname;

        offset = cache_info->dnsrch_offset;
@@ -1835,13 +1836,13 @@ void _resolv_populate_res_for_net(res_state statp) { 
    if (statp == NULL) {

        return;

    }

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



    std::lock_guard guard(cache_mutex);

    resolv_cache_info* info = find_cache_info_locked(statp->netid);

    if (info != NULL) {

        int nserv;

        struct addrinfo* ai;

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

        for (nserv = 0; nserv < MAXNS; nserv++) {

            ai = info->nsaddrinfo[nserv];

            if (ai == NULL) {

res_debug.cpp

+8 −52
Original line number Diff line number Diff line
@@ -95,6 +95,8 @@ 
 * IF IBM IS APPRISED OF THE POSSIBILITY OF SUCH DAMAGES.

 */



#define LOG_TAG "res_debug"



#include <sys/param.h>

#include <sys/socket.h>

#include <sys/types.h>
@@ -108,7 +110,6 @@ 
#include <errno.h>

#include <math.h>

#include <netdb.h>

#include <stdio.h>

#include <stdlib.h>

#include <string.h>

#include <strings.h>
@@ -122,7 +123,8 @@ struct res_sym { 
    const char* humanname; /* Its fun name, like "mail exchanger" */

};



/* add a formatted string to a bounded buffer */

// add a formatted string to a bounded buffer

// TODO: convert to std::string

static char* dbprint(char* p, char* end, const char* format, ...) {

    int avail, n;

    va_list args;
@@ -144,6 +146,7 @@ static char* dbprint(char* p, char* end, const char* format, ...) { 


    return p;

}



static void do_section(const res_state statp, ns_msg* handle, ns_sect section, int pflag) {

    int n, sflag, rrnum;

    int buflen = 2048;
@@ -258,8 +261,9 @@ cleanup: 
 * Print the contents of a query.

 * This is intended to be primarily a debugging routine.

 */



void res_pquery(const res_state statp, const u_char* msg, int len) {

    if (!WOULD_LOG(VERBOSE)) return;



    ns_msg handle;

    int qdcount, ancount, nscount, arcount;

    u_int opcode, rcode, id;
@@ -301,9 +305,7 @@ void res_pquery(const res_state statp, const u_char* msg, int len) { 
        p = dbprint(p, end, ", %s: %d", p_section(ns_s_ns, (int)opcode), nscount);

        p = dbprint(p, end, ", %s: %d", p_section(ns_s_ar, (int)opcode), arcount);

    }

    if ((!statp->pfcode) || (statp->pfcode & (RES_PRF_HEADX | RES_PRF_HEAD2 | RES_PRF_HEAD1))) {

        p = dbprint(p, end, " \n");

    }



    LOG(VERBOSE) << temp;



    /*
@@ -316,52 +318,6 @@ void res_pquery(const res_state statp, const u_char* msg, int len) { 
    if (qdcount == 0 && ancount == 0 && nscount == 0 && arcount == 0) LOG(VERBOSE) << ";;";

}



const u_char* p_cdnname(const u_char* cp, const u_char* msg, int len, FILE* file) {

    char name[MAXDNAME];

    int n;



    if ((n = dn_expand(msg, msg + len, cp, name, (int) sizeof name)) < 0) return (NULL);

    if (name[0] == '\0')

        putc('.', file);

    else

        fputs(name, file);

    return (cp + n);

}



const u_char* p_cdname(const u_char* cp, const u_char* msg, FILE* file) {

    return (p_cdnname(cp, msg, PACKETSZ, file));

}



/* Return a fully-qualified domain name from a compressed name (with

   length supplied).  */



const u_char* p_fqnname(const u_char* cp, const u_char* msg, int msglen, char* name, int namelen) {

    int n;

    size_t newlen;



    if ((n = dn_expand(msg, cp + msglen, cp, name, namelen)) < 0) return (NULL);

    newlen = strlen(name);

    if (newlen == 0 || name[newlen - 1] != '.') {

        if ((int) newlen + 1 >= namelen) /* Lack space for final dot */

            return (NULL);

        else

            strcpy(name + newlen, ".");

    }

    return (cp + n);

}



/* XXX:	the rest of these functions need to become length-limited, too. */



const u_char* p_fqname(const u_char* cp, const u_char* msg, FILE* file) {

    char name[MAXDNAME];

    const u_char* n;



    n = p_fqnname(cp, msg, MAXCDNAME, name, (int) sizeof name);

    if (n == NULL) return (NULL);

    fputs(name, file);

    return (n);

}



/*

 * Names of RR classes and qclasses.  Classes and qclasses are the same, except

 * that C_ANY is a qclass but not a class.  (You can ask for records of class

res_init.cpp

+5 −3
Original line number Diff line number Diff line
@@ -69,6 +69,9 @@ 
 * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT

 * OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.

 */



#define LOG_TAG "res_init"



#include <sys/param.h>

#include <sys/socket.h>

#include <sys/time.h>
@@ -187,9 +190,8 @@ int res_vinit(res_state statp, int preinit) { 
            dots--;

        }

        *pp = NULL;

        LOG(DEBUG) << ";; res_init()... default dnsrch list:";

        for (pp = statp->dnsrch; *pp; pp++) LOG(DEBUG) << ";;\t" << *pp;

        LOG(DEBUG) << ";;\t..END..";

        LOG(DEBUG) << "res_init(): dnsrch list:";

        for (pp = statp->dnsrch; *pp; pp++) LOG(DEBUG) << "\t" << *pp;

    }



    if ((cp = getenv("RES_OPTIONS")) != NULL) res_setoptions(statp, cp, "env");