resolv: Switch to android-base/logging.h
This moves us away from async_safe_format_log() so we can drop the
last remaining dependency on internal bionic headers.
The debug logging code has bitrotten for a very long time and didn't
even compile any more, and when it finally did I noticed that
dump_answer() was trying to create a temporary file in /data on each
cache insert! Plenty of room for future improvements.
Test: m netd_integration_test
Test: build with kVerboseLogging=true in all modules and check logcat
Change-Id: I5d8c4b207f1477e75476b06b863a7d1723664407
diff --git a/resolv/Android.bp b/resolv/Android.bp
index 5c5dfc7..845b59f 100644
--- a/resolv/Android.bp
+++ b/resolv/Android.bp
@@ -16,11 +16,18 @@
"res_state.cpp",
"res_stats.cpp",
],
- // TODO: stop depending on internal bionic headers
- include_dirs: [
- "bionic/libc/async_safe/include", // For async_safe/log.h
+ static_libs: [
+ "libbase",
+ "liblog",
],
export_include_dirs: ["."], // Export resolv_netid.h
// TODO: pie in the sky: make this code clang-tidy clean
- tidy: false
+ tidy: false,
+ product_variables: {
+ debuggable: {
+ cppflags: [
+ "-DRESOLV_ALLOW_VERBOSE_LOGGING=1",
+ ],
+ },
+ },
}
diff --git a/resolv/res_cache.cpp b/resolv/res_cache.cpp
index 4d13126..b298b39 100644
--- a/resolv/res_cache.cpp
+++ b/resolv/res_cache.cpp
@@ -26,6 +26,12 @@
* 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 kVerboseLogging = false;
+constexpr bool kDumpData = false;
+#define LOG_TAG "res_cache"
+
#include <pthread.h>
#include <resolv.h>
#include <stdarg.h>
@@ -34,20 +40,27 @@
#include <string.h>
#include <time.h>
+#include <arpa/inet.h>
#include <arpa/nameser.h>
#include <errno.h>
#include <linux/if.h>
#include <net/if.h>
#include <netdb.h>
-#include <arpa/inet.h>
+#include <android-base/logging.h>
#include "res_private.h"
#include "resolv_cache.h"
#include "resolv_netid.h"
#include "resolv_private.h"
-#include <async_safe/log.h>
+#define VLOG if (!kVerboseLogging) {} else LOG(INFO)
+
+#ifndef RESOLV_ALLOW_VERBOSE_LOGGING
+static_assert(kVerboseLogging == false && kDumpData == false,
+ "Verbose logging floods logs at high-rate and exposes privacy-sensitive information. "
+ "Do not enable in release builds.");
+#endif
/* This code implements a small and *simple* DNS resolver cache.
*
@@ -129,24 +142,7 @@
* * Upping by another 5x for the centralized nature
* *****************************************
*/
-#define CONFIG_MAX_ENTRIES 64 * 2 * 5
-
-/* set to 1 to debug cache operations */
-#define DEBUG 0
-
-/* set to 1 to debug query data */
-#define DEBUG_DATA 0
-
-#undef XLOG
-
-#define XLOG(...) \
- ({ \
- if (DEBUG) { \
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", __VA_ARGS__); \
- } else { \
- ((void) 0); \
- } \
- })
+#define CONFIG_MAX_ENTRIES (64 * 2 * 5)
/** BOUNDED BUFFER FORMATTING **/
@@ -164,25 +160,25 @@
* IMPORTANT: it is assumed that end > buffer_address, i.e.
* that the buffer is at least one byte.
*
- * the _bprint_() functions return the new value of 'p' after the data
+ * the bprint_x() functions return the new value of 'p' after the data
* has been appended, and also ensure the following:
*
* - the returned value will never be strictly greater than 'end'
*
- * - a return value equal to 'end' means that truncation occured
+ * - a return value equal to 'end' means that truncation occurred
* (in which case, end[-1] will be set to 0)
*
- * - after returning from a _bprint_() function, the content of the buffer
+ * - after returning from a bprint_x() function, the content of the buffer
* is always 0-terminated, even in the event of truncation.
*
- * these conventions allow you to call _bprint_ functions multiple times and
+ * these conventions allow you to call bprint_x() functions multiple times and
* only check for truncation at the end of the sequence, as in:
*
* char buff[1000], *p = buff, *end = p + sizeof(buff);
*
- * p = _bprint_c(p, end, '"');
- * p = _bprint_s(p, end, my_string);
- * p = _bprint_c(p, end, '"');
+ * p = bprint_c(p, end, '"');
+ * p = bprint_s(p, end, my_string);
+ * p = bprint_c(p, end, '"');
*
* if (p >= end) {
* // buffer was too small
@@ -192,7 +188,7 @@
*/
/* add a char to a bounded buffer */
-static char* _bprint_c(char* p, char* end, int c) {
+static char* bprint_c(char* p, char* end, int c) {
if (p < end) {
if (p + 1 == end)
*p++ = 0;
@@ -205,7 +201,7 @@
}
/* add a sequence of bytes to a bounded buffer */
-static char* _bprint_b(char* p, char* end, const char* buf, int len) {
+static char* bprint_b(char* p, char* end, const char* buf, int len) {
int avail = end - p;
if (avail <= 0 || len <= 0) return p;
@@ -224,12 +220,12 @@
}
/* add a string to a bounded buffer */
-static char* _bprint_s(char* p, char* end, const char* str) {
- return _bprint_b(p, end, str, strlen(str));
+static char* bprint_s(char* p, char* end, const char* str) {
+ return bprint_b(p, end, str, strlen(str));
}
/* add a formatted string to a bounded buffer */
-[[maybe_unused]] static char* _bprint(char* p, char* end, const char* format, ...) {
+static char* bprint(char* p, char* end, const char* format, ...) {
int avail, n;
va_list args;
@@ -252,18 +248,18 @@
}
/* add a hex value to a bounded buffer, up to 8 digits */
-static char* _bprint_hex(char* p, char* end, unsigned value, int numDigits) {
+static char* bprint_hex(char* p, char* end, unsigned value, int numDigits) {
char text[sizeof(unsigned) * 2];
int nn = 0;
while (numDigits-- > 0) {
text[nn++] = "0123456789abcdef"[(value >> (numDigits * 4)) & 15];
}
- return _bprint_b(p, end, text, nn);
+ return bprint_b(p, end, text, nn);
}
/* add the hexadecimal dump of some memory area to a bounded buffer */
-static char* _bprint_hexdump(char* p, char* end, const uint8_t* data, int datalen) {
+static char* bprint_hexdump(char* p, char* end, const uint8_t* data, int datalen) {
int lineSize = 16;
while (datalen > 0) {
@@ -273,22 +269,22 @@
if (avail > lineSize) avail = lineSize;
for (nn = 0; nn < avail; nn++) {
- if (nn > 0) p = _bprint_c(p, end, ' ');
- p = _bprint_hex(p, end, data[nn], 2);
+ if (nn > 0) p = bprint_c(p, end, ' ');
+ p = bprint_hex(p, end, data[nn], 2);
}
for (; nn < lineSize; nn++) {
- p = _bprint_s(p, end, " ");
+ p = bprint_s(p, end, " ");
}
- p = _bprint_s(p, end, " ");
+ p = bprint_s(p, end, " ");
for (nn = 0; nn < avail; nn++) {
int c = data[nn];
if (c < 32 || c > 127) c = '.';
- p = _bprint_c(p, end, c);
+ p = bprint_c(p, end, c);
}
- p = _bprint_c(p, end, '\n');
+ p = bprint_c(p, end, '\n');
data += avail;
datalen -= avail;
@@ -297,14 +293,14 @@
}
/* dump the content of a query of packet to the log */
-[[maybe_unused]] static void XLOG_BYTES(const uint8_t* base, int len) {
- if (DEBUG_DATA) {
- char buff[1024];
- char *p = buff, *end = p + sizeof(buff);
+static void dump_bytes(const uint8_t* base, int len) {
+ if (!kDumpData) return;
- p = _bprint_hexdump(p, end, base, len);
- XLOG("%s", buff);
- }
+ char buff[1024];
+ char *p = buff, *end = p + sizeof(buff);
+
+ p = bprint_hexdump(p, end, base, len);
+ VLOG << buff;
}
static time_t _time_now(void) {
@@ -486,7 +482,7 @@
* of the loop here */
}
/* malformed data */
- XLOG("malformed QNAME");
+ VLOG << "malformed QNAME";
return 0;
}
@@ -502,12 +498,12 @@
!_dnsPacket_checkBytes(packet, 2, DNS_TYPE_MX) &&
!_dnsPacket_checkBytes(packet, 2, DNS_TYPE_AAAA) &&
!_dnsPacket_checkBytes(packet, 2, DNS_TYPE_ALL)) {
- XLOG("unsupported TYPE");
+ VLOG << "unsupported TYPE";
return 0;
}
/* CLASS must be IN */
if (!_dnsPacket_checkBytes(packet, 2, DNS_CLASS_IN)) {
- XLOG("unsupported CLASS");
+ VLOG << "unsupported CLASS";
return 0;
}
@@ -522,14 +518,14 @@
int qdCount, anCount, dnCount, arCount;
if (p + DNS_HEADER_SIZE > packet->end) {
- XLOG("query packet too small");
+ VLOG << "query packet too small";
return 0;
}
/* QR must be set to 0, opcode must be 0 and AA must be 0 */
/* RA, Z, and RCODE must be 0 */
if ((p[2] & 0xFC) != 0 || (p[3] & 0xCF) != 0) {
- XLOG("query packet flags unsupported");
+ VLOG << "query packet flags unsupported";
return 0;
}
@@ -558,12 +554,12 @@
arCount = (p[10] << 8) | p[11];
if (anCount != 0 || dnCount != 0 || arCount > 1) {
- XLOG("query packet contains non-query records");
+ VLOG << "query packet contains non-query records";
return 0;
}
if (qdCount == 0) {
- XLOG("query packet doesn't contain query record");
+ VLOG << "query packet doesn't contain query record";
return 0;
}
@@ -577,8 +573,7 @@
}
/** QUERY DEBUGGING **/
-#if DEBUG
-static char* _dnsPacket_bprintQName(DnsPacket* packet, char* bp, char* bend) {
+static char* dnsPacket_bprintQName(DnsPacket* packet, char* bp, char* bend) {
const uint8_t* p = packet->cursor;
const uint8_t* end = packet->end;
int first = 1;
@@ -601,20 +596,20 @@
if (first)
first = 0;
else
- bp = _bprint_c(bp, bend, '.');
+ bp = bprint_c(bp, bend, '.');
- bp = _bprint_b(bp, bend, (const char*) p, c);
+ bp = bprint_b(bp, bend, (const char*) p, c);
p += c;
/* we rely on the bound check at the start
* of the loop here */
}
/* malformed data */
- bp = _bprint_s(bp, bend, "<MALFORMED>");
+ bp = bprint_s(bp, bend, "<MALFORMED>");
return bp;
}
-static char* _dnsPacket_bprintQR(DnsPacket* packet, char* p, char* end) {
+static char* dnsPacket_bprintQR(DnsPacket* packet, char* p, char* end) {
#define QQ(x) \
{ DNS_TYPE_##x, #x }
static const struct {
@@ -625,10 +620,10 @@
const char* typeString = NULL;
/* dump QNAME */
- p = _dnsPacket_bprintQName(packet, p, end);
+ p = dnsPacket_bprintQName(packet, p, end);
/* dump TYPE */
- p = _bprint_s(p, end, " (");
+ p = bprint_s(p, end, " (");
for (nn = 0; qTypes[nn].typeBytes != NULL; nn++) {
if (_dnsPacket_checkBytes(packet, 2, qTypes[nn].typeBytes)) {
@@ -638,13 +633,13 @@
}
if (typeString != NULL)
- p = _bprint_s(p, end, typeString);
+ p = bprint_s(p, end, typeString);
else {
int typeCode = _dnsPacket_readInt16(packet);
- p = _bprint(p, end, "UNKNOWN-%d", typeCode);
+ p = bprint(p, end, "UNKNOWN-%d", typeCode);
}
- p = _bprint_c(p, end, ')');
+ p = bprint_c(p, end, ')');
/* skip CLASS */
_dnsPacket_skip(packet, 2);
@@ -652,11 +647,11 @@
}
/* this function assumes the packet has already been checked */
-static char* _dnsPacket_bprintQuery(DnsPacket* packet, char* p, char* end) {
+static char* dnsPacket_bprintQuery(DnsPacket* packet, char* p, char* end) {
int qdCount;
if (packet->base[2] & 0x1) {
- p = _bprint_s(p, end, "RECURSIVE ");
+ p = bprint_s(p, end, "RECURSIVE ");
}
_dnsPacket_skip(packet, 4);
@@ -664,11 +659,10 @@
_dnsPacket_skip(packet, 6);
for (; qdCount > 0; qdCount--) {
- p = _dnsPacket_bprintQR(packet, p, end);
+ p = dnsPacket_bprintQR(packet, p, end);
}
return p;
}
-#endif
/** QUERY HASHING SUPPORT
**
@@ -699,7 +693,7 @@
int c;
if (p >= end) { /* should not happen */
- XLOG("%s: INTERNAL_ERROR: read-overflow !!\n", __FUNCTION__);
+ VLOG << __func__ << ": INTERNAL_ERROR: read-overflow";
break;
}
@@ -708,11 +702,11 @@
if (c == 0) break;
if (c >= 64) {
- XLOG("%s: INTERNAL_ERROR: malformed domain !!\n", __FUNCTION__);
+ VLOG << __func__ << ": INTERNAL_ERROR: malformed domain";
break;
}
if (p + c >= end) {
- XLOG("%s: INTERNAL_ERROR: simple label read-overflow !!\n", __FUNCTION__);
+ VLOG << __func__ << ": INTERNAL_ERROR: simple label read-overflow";
break;
}
while (c > 0) {
@@ -783,7 +777,7 @@
/** QUERY COMPARISON
**
** THE FOLLOWING CODE ASSUMES THAT THE INPUT PACKETS HAVE ALREADY
- ** BEEN SUCCESFULLY CHECKED.
+ ** BEEN SUCCESSFULLY CHECKED.
**/
static int _dnsPacket_isEqualDomainName(DnsPacket* pack1, DnsPacket* pack2) {
@@ -796,7 +790,7 @@
int c1, c2;
if (p1 >= end1 || p2 >= end2) {
- XLOG("%s: INTERNAL_ERROR: read-overflow !!\n", __FUNCTION__);
+ VLOG << __func__ << ": INTERNAL_ERROR: read-overflow";
break;
}
c1 = *p1++;
@@ -809,11 +803,11 @@
return 1;
}
if (c1 >= 64) {
- XLOG("%s: INTERNAL_ERROR: malformed domain !!\n", __FUNCTION__);
+ VLOG << __func__ << ": INTERNAL_ERROR: malformed domain";
break;
}
if ((p1 + c1 > end1) || (p2 + c1 > end2)) {
- XLOG("%s: INTERNAL_ERROR: simple label read-overflow !!\n", __FUNCTION__);
+ VLOG << __func__ << ": INTERNAL_ERROR: simple label read-overflow";
break;
}
if (memcmp(p1, p2, c1) != 0) break;
@@ -822,7 +816,7 @@
/* we rely on the bound checks at the start of the loop */
}
/* not the same, or one is malformed */
- XLOG("different DN");
+ VLOG << "different DN";
return 0;
}
@@ -870,12 +864,12 @@
/* compare RD, ignore TC, see comment in _dnsPacket_checkQuery */
if ((pack1->base[2] & 1) != (pack2->base[2] & 1)) {
- XLOG("different RD");
+ VLOG << "different RD";
return 0;
}
if (pack1->base[3] != pack2->base[3]) {
- XLOG("different CD or AD");
+ VLOG << "different CD or AD";
return 0;
}
@@ -887,7 +881,7 @@
count1 = _dnsPacket_readInt16(pack1);
count2 = _dnsPacket_readInt16(pack2);
if (count1 != count2 || count1 < 0) {
- XLOG("different QDCOUNT");
+ VLOG << "different QDCOUNT";
return 0;
}
@@ -899,14 +893,14 @@
arcount1 = _dnsPacket_readInt16(pack1);
arcount2 = _dnsPacket_readInt16(pack2);
if (arcount1 != arcount2 || arcount1 < 0) {
- XLOG("different ARCOUNT");
+ VLOG << "different ARCOUNT";
return 0;
}
/* compare the QDCOUNT QRs */
for (; count1 > 0; count1--) {
if (!_dnsPacket_isEqualQR(pack1, pack2)) {
- XLOG("different QR");
+ VLOG << "different QR";
return 0;
}
}
@@ -914,7 +908,7 @@
/* compare the ARCOUNT RRs */
for (; arcount1 > 0; arcount1--) {
if (!_dnsPacket_isEqualRR(pack1, pack2)) {
- XLOG("different additional RR");
+ VLOG << "different additional RR";
return 0;
}
}
@@ -1021,16 +1015,16 @@
result = ttl;
}
} else {
- XLOG("ns_parserr failed ancount no = %d. errno = %s\n", n, strerror(errno));
+ VLOG << "ns_parserr failed ancount no = "
+ << n << ". errno = " << strerror(errno);
}
}
}
} else {
- XLOG("ns_parserr failed. %s\n", strerror(errno));
+ VLOG << "ns_initparse failed: " << strerror(errno);
}
- XLOG("TTL = %lu\n", result);
-
+ VLOG << "TTL = " << result;
return result;
}
@@ -1219,7 +1213,7 @@
}
} else {
struct timespec ts = {0, 0};
- XLOG("Waiting for previous request");
+ VLOG << "Waiting for previous request";
ts.tv_sec = _time_now() + PENDING_REQUEST_TIMEOUT;
pthread_cond_timedwait(&ri->cond, &_res_cache_list_lock, &ts);
/* Must update *cache as it could have been deleted. */
@@ -1296,9 +1290,7 @@
cache->num_entries = 0;
cache->last_id = 0;
- XLOG("*************************\n"
- "*** DNS CACHE FLUSHED ***\n"
- "*************************");
+ VLOG << "*** DNS CACHE FLUSHED ***";
}
static int _res_cache_get_max_entries(void) {
@@ -1310,7 +1302,7 @@
cache_size = 0;
}
- XLOG("cache size: %d", cache_size);
+ VLOG << "cache size: " << cache_size;
return cache_size;
}
@@ -1323,7 +1315,7 @@
cache->entries = (Entry*) calloc(sizeof(*cache->entries), cache->max_entries);
if (cache->entries) {
cache->mru_list.mru_prev = cache->mru_list.mru_next = &cache->mru_list;
- XLOG("%s: cache created\n", __FUNCTION__);
+ VLOG << __func__ << ": cache created";
} else {
free(cache);
cache = NULL;
@@ -1332,28 +1324,34 @@
return cache;
}
-#if DEBUG
-static void _dump_query(const uint8_t* query, int querylen) {
+static void dump_query(const uint8_t* query, int querylen) {
+ if (!kVerboseLogging) return;
+
char temp[256], *p = temp, *end = p + sizeof(temp);
DnsPacket pack[1];
_dnsPacket_init(pack, query, querylen);
- p = _dnsPacket_bprintQuery(pack, p, end);
- XLOG("QUERY: %s", temp);
+ p = dnsPacket_bprintQuery(pack, p, end);
+ VLOG << temp;
}
-static void _cache_dump_mru(Cache* cache) {
+static void cache_dump_mru(Cache* cache) {
+ if (!kVerboseLogging) return;
+
char temp[512], *p = temp, *end = p + sizeof(temp);
Entry* e;
- p = _bprint(temp, end, "MRU LIST (%2d): ", cache->num_entries);
+ p = bprint(temp, end, "MRU LIST (%2d): ", cache->num_entries);
for (e = cache->mru_list.mru_next; e != &cache->mru_list; e = e->mru_next)
- p = _bprint(p, end, " %d", e->id);
+ p = bprint(p, end, " %d", e->id);
- XLOG("%s", temp);
+ VLOG << temp;
}
-static void _dump_answer(const void* answer, int answerlen) {
+// TODO: Rewrite to avoid creating a file in /data as temporary buffer (WAT).
+static void dump_answer(const u_char* answer, int answerlen) {
+ if (!kVerboseLogging) return;
+
res_state statep;
FILE* fp;
char* buf;
@@ -1373,25 +1371,16 @@
if (buf != NULL) {
// Read file contents into buffer
fread(buf, fileLen, 1, fp);
- XLOG("%s\n", buf);
+ VLOG << buf;
free(buf);
}
fclose(fp);
remove("/data/reslog.txt");
} else {
errno = 0; // else debug is introducing error signals
- XLOG("%s: can't open file\n", __FUNCTION__);
+ VLOG << __func__ << ": can't open file";
}
}
-#endif
-
-#if DEBUG
-#define XLOG_QUERY(q, len) _dump_query((q), (len))
-#define XLOG_ANSWER(a, len) _dump_answer((a), (len))
-#else
-#define XLOG_QUERY(q, len) ((void) 0)
-#define XLOG_ANSWER(a, len) ((void) 0)
-#endif
/* This function tries to find a key within the hash table
* In case of success, it will return a *pointer* to the hashed key.
@@ -1434,7 +1423,7 @@
entry_mru_add(e, &cache->mru_list);
cache->num_entries += 1;
- XLOG("%s: entry %d added (count=%d)", __FUNCTION__, e->id, cache->num_entries);
+ VLOG << __func__ << ": entry " << e->id << " added (count=" << cache->num_entries << ")";
}
/* Remove an existing entry from the hash table,
@@ -1444,7 +1433,7 @@
static void _cache_remove_p(Cache* cache, Entry** lookup) {
Entry* e = *lookup;
- XLOG("%s: entry %d removed (count=%d)", __FUNCTION__, e->id, cache->num_entries - 1);
+ VLOG << __func__ << ": entry " << e->id << " removed (count=" << cache->num_entries - 1 << ")";
entry_mru_remove(e);
*lookup = e->hlink;
@@ -1459,13 +1448,11 @@
Entry** lookup = _cache_lookup_p(cache, oldest);
if (*lookup == NULL) { /* should not happen */
- XLOG("%s: OLDEST NOT IN HTABLE ?", __FUNCTION__);
+ VLOG << __func__ << ": OLDEST NOT IN HTABLE ?";
return;
}
- if (DEBUG) {
- XLOG("Cache full - removing oldest");
- XLOG_QUERY(oldest->query, oldest->querylen);
- }
+ VLOG << "Cache full - removing oldest";
+ dump_query(oldest->query, oldest->querylen);
_cache_remove_p(cache, lookup);
}
@@ -1480,7 +1467,7 @@
if (now >= e->expires) {
Entry** lookup = _cache_lookup_p(cache, e);
if (*lookup == NULL) { /* should not happen */
- XLOG("%s: ENTRY NOT IN HTABLE ?", __FUNCTION__);
+ VLOG << __func__ << ": ENTRY NOT IN HTABLE ?";
return;
}
e = e->mru_next;
@@ -1501,12 +1488,12 @@
ResolvCacheStatus result = RESOLV_CACHE_NOTFOUND;
- XLOG("%s: lookup", __FUNCTION__);
- XLOG_QUERY(query, querylen);
+ VLOG << __func__ << ": lookup";
+ dump_query((u_char*) query, querylen);
/* we don't cache malformed queries */
if (!entry_init_key(key, query, querylen)) {
- XLOG("%s: unsupported query", __FUNCTION__);
+ VLOG << __func__ << ": unsupported query";
return RESOLV_CACHE_UNSUPPORTED;
}
/* lookup cache */
@@ -1526,7 +1513,7 @@
e = *lookup;
if (e == NULL) {
- XLOG("NOT IN CACHE");
+ VLOG << "NOT IN CACHE";
// calling thread will wait if an outstanding request is found
// that matching this query
if (!_cache_check_pending_request_locked(&cache, key, netid) || cache == NULL) {
@@ -1544,8 +1531,8 @@
/* remove stale entries here */
if (now >= e->expires) {
- XLOG(" NOT IN CACHE (STALE ENTRY %p DISCARDED)", *lookup);
- XLOG_QUERY(e->query, e->querylen);
+ VLOG << " NOT IN CACHE (STALE ENTRY " << *lookup << "DISCARDED)";
+ dump_query(e->query, e->querylen);
_cache_remove_p(cache, lookup);
goto Exit;
}
@@ -1554,7 +1541,7 @@
if (e->answerlen > answersize) {
/* NOTE: we return UNSUPPORTED if the answer buffer is too short */
result = RESOLV_CACHE_UNSUPPORTED;
- XLOG(" ANSWER TOO LONG");
+ VLOG << " ANSWER TOO LONG";
goto Exit;
}
@@ -1566,7 +1553,7 @@
entry_mru_add(e, &cache->mru_list);
}
- XLOG("FOUND IN CACHE entry=%p", e);
+ VLOG << "FOUND IN CACHE entry=" << e;
result = RESOLV_CACHE_FOUND;
Exit:
@@ -1585,7 +1572,7 @@
/* don't assume that the query has already been cached
*/
if (!entry_init_key(key, query, querylen)) {
- XLOG("%s: passed invalid query ?", __FUNCTION__);
+ VLOG << __func__ << ": passed invalid query?";
return;
}
@@ -1596,19 +1583,19 @@
goto Exit;
}
- XLOG("%s: query:", __FUNCTION__);
- XLOG_QUERY(query, querylen);
- XLOG_ANSWER(answer, answerlen);
-#if DEBUG_DATA
- XLOG("answer:");
- XLOG_BYTES(answer, answerlen);
-#endif
+ VLOG << __func__ << ": query:";
+ dump_query((u_char*) query, querylen);
+ dump_answer((u_char*) answer, answerlen);
+ if (kDumpData) {
+ VLOG << "answer:";
+ dump_bytes((u_char*) answer, answerlen);
+ }
lookup = _cache_lookup_p(cache, key);
e = *lookup;
if (e != NULL) { /* should not happen */
- XLOG("%s: ALREADY IN CACHE (%p) ? IGNORING ADD", __FUNCTION__, e);
+ VLOG << __func__ << ": ALREADY IN CACHE (" << e << ") ? IGNORING ADD";
goto Exit;
}
@@ -1621,7 +1608,7 @@
lookup = _cache_lookup_p(cache, key);
e = *lookup;
if (e != NULL) {
- XLOG("%s: ALREADY IN CACHE (%p) ? IGNORING ADD", __FUNCTION__, e);
+ VLOG << __func__ << ": ALREADY IN CACHE (" << e << ") ? IGNORING ADD";
goto Exit;
}
}
@@ -1634,9 +1621,8 @@
_cache_add_p(cache, lookup, e);
}
}
-#if DEBUG
- _cache_dump_mru(cache);
-#endif
+ cache_dump_mru(cache);
+
Exit:
if (cache != NULL) {
_cache_notify_waiting_tid_locked(cache, key);
@@ -1779,7 +1765,7 @@
struct addrinfo* nsaddrinfo[MAXNS];
if (numservers > MAXNS) {
- XLOG("%s: numservers=%u, MAXNS=%u", __FUNCTION__, numservers, MAXNS);
+ VLOG << __func__ << ": numservers=" << numservers << ", MAXNS=" << MAXNS;
return E2BIG;
}
@@ -1796,7 +1782,7 @@
freeaddrinfo(nsaddrinfo[j]);
nsaddrinfo[j] = NULL;
}
- XLOG("%s: getaddrinfo(%s)=%s", __FUNCTION__, servers[i], gai_strerror(rt));
+ VLOG << __func__ << ": getaddrinfo(" << servers[i] << ") = " << gai_strerror(rt);
return EINVAL;
}
}
@@ -1824,7 +1810,7 @@
for (i = 0; i < numservers; i++) {
cache_info->nsaddrinfo[i] = nsaddrinfo[i];
cache_info->nameservers[i] = strdup(servers[i]);
- XLOG("%s: netid = %u, addr = %s\n", __FUNCTION__, netid, servers[i]);
+ VLOG << __func__ << ": netid = " << netid << ", addr = " << servers[i];
}
cache_info->nscount = numservers;
@@ -1931,7 +1917,7 @@
if (info != NULL) {
int nserv;
struct addrinfo* ai;
- XLOG("%s: %u\n", __FUNCTION__, statp->netid);
+ VLOG << __func__ << ": " << statp->netid;
for (nserv = 0; nserv < MAXNS; nserv++) {
ai = info->nsaddrinfo[nserv];
if (ai == NULL) {
@@ -1950,7 +1936,7 @@
}
}
} else {
- XLOG("%s: found too long addrlen", __FUNCTION__);
+ VLOG << __func__ << ": found too long addrlen";
}
}
statp->nscount = nserv;
@@ -1973,8 +1959,8 @@
const struct __res_sample* 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
- XLOG("%s: adding sample to stats, next = %d, count = %d", __FUNCTION__, stats->sample_next,
- stats->sample_count);
+ VLOG << __func__ << ": adding sample to stats, next = " << stats->sample_next
+ << ", count = " << stats->sample_count;
stats->samples[stats->sample_next] = *sample;
if (stats->sample_count < max_samples) {
++stats->sample_count;
@@ -2004,7 +1990,7 @@
if (info) {
if (info->nscount > MAXNS) {
pthread_mutex_unlock(&_res_cache_list_lock);
- XLOG("%s: nscount %d > MAXNS %d", __FUNCTION__, info->nscount, MAXNS);
+ VLOG << __func__ << ": nscount " << info->nscount << " > MAXNS " << MAXNS;
errno = EFAULT;
return -1;
}
@@ -2017,19 +2003,19 @@
int addrlen = info->nsaddrinfo[i]->ai_addrlen;
if (addrlen < (int) sizeof(struct sockaddr) || addrlen > (int) sizeof(servers[0])) {
pthread_mutex_unlock(&_res_cache_list_lock);
- XLOG("%s: nsaddrinfo[%d].ai_addrlen == %d", __FUNCTION__, i, addrlen);
+ VLOG << __func__ << ": nsaddrinfo[" << i << "].ai_addrlen == " << addrlen;
errno = EMSGSIZE;
return -1;
}
if (info->nsaddrinfo[i]->ai_addr == NULL) {
pthread_mutex_unlock(&_res_cache_list_lock);
- XLOG("%s: nsaddrinfo[%d].ai_addr == NULL", __FUNCTION__, i);
+ VLOG << __func__ << ": nsaddrinfo[" << i << "].ai_addr == NULL";
errno = ENOENT;
return -1;
}
if (info->nsaddrinfo[i]->ai_next != NULL) {
pthread_mutex_unlock(&_res_cache_list_lock);
- XLOG("%s: nsaddrinfo[%d].ai_next != NULL", __FUNCTION__, i);
+ VLOG << __func__ << ": nsaddrinfo[" << i << "].ai_next != NULL";
errno = ENOTUNIQ;
return -1;
}
diff --git a/resolv/res_debug.h b/resolv/res_debug.h
deleted file mode 100644
index ea2744b..0000000
--- a/resolv/res_debug.h
+++ /dev/null
@@ -1,42 +0,0 @@
-/* $NetBSD: res_debug.h,v 1.1.1.1 2004/05/20 17:18:55 christos Exp $ */
-
-/*
- * Copyright (c) 2004 by Internet Systems Consortium, Inc. ("ISC")
- * Copyright (c) 1999 by Internet Software Consortium.
- *
- * Permission to use, copy, modify, and distribute this software for any
- * purpose with or without fee is hereby granted, provided that the above
- * copyright notice and this permission notice appear in all copies.
- *
- * THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES
- * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
- * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL ISC BE LIABLE FOR
- * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
- * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
- * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT
- * OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
- */
-
-#ifndef _RES_DEBUG_H_
-#define _RES_DEBUG_H_
-
-#ifndef DEBUG
-#define Dprint(cond, args) /*empty*/
-#define DprintQ(cond, args, query, size) /*empty*/
-#define Aerror(statp, file, string, error, address) /*empty*/
-#define Perror(statp, file, string, error) /*empty*/
-#else
-#define Dprint(cond, args) \
- if (cond) { \
- fprintf args; \
- } else { \
- }
-#define DprintQ(cond, args, query, size) \
- if (cond) { \
- fprintf args; \
- res_pquery(statp, query, size, stdout); \
- } else { \
- }
-#endif
-
-#endif /* _RES_DEBUG_H_ */
diff --git a/resolv/res_send.cpp b/resolv/res_send.cpp
index fad08ee..ad655c9 100644
--- a/resolv/res_send.cpp
+++ b/resolv/res_send.cpp
@@ -74,6 +74,9 @@
* Send query to name server and wait for reply.
*/
+constexpr bool kVerboseLogging = false;
+#define LOG_TAG "res_send"
+
#include <sys/param.h>
#include <sys/socket.h>
#include <sys/time.h>
@@ -95,7 +98,7 @@
#include <time.h>
#include <unistd.h>
-#include <async_safe/log.h>
+#include <android-base/logging.h>
#include "private/android_filesystem_config.h"
#include "res_private.h"
@@ -104,17 +107,33 @@
#include "resolv_private.h"
#include "resolv_stats.h"
-/* Options. Leave them on. */
-#ifndef DEBUG
-#define DEBUG
+#define EXT(res) ((res)->_u._ext)
+
+#define VLOG if (!kVerboseLogging) {} else LOG(INFO)
+
+#ifndef RESOLV_ALLOW_VERBOSE_LOGGING
+static_assert(kVerboseLogging == false,
+ "Verbose logging floods logs at high-rate and exposes privacy-sensitive information. "
+ "Do not enable in release builds.");
#endif
-#include "res_debug.h"
-
-#define EXT(res) ((res)->_u._ext)
-#define DBG 0
-
-/* Forward. */
+#ifndef DEBUG
+#define Dprint(cond, args) /*empty*/
+#define DprintQ(cond, args, query, size) /*empty*/
+#else
+// TODO: convert to Android logging
+#define Dprint(cond, args) \
+ if (cond) { \
+ fprintf args; \
+ } else { \
+ }
+#define DprintQ(cond, args, query, size) \
+ if (cond) { \
+ fprintf args; \
+ res_pquery(statp, query, size, stdout); \
+ } else { \
+ }
+#endif // DEBUG
static int get_salen(const struct sockaddr*);
static struct sockaddr* get_nsaddr(res_state, size_t);
@@ -125,7 +144,6 @@
static void Aerror(const res_state, FILE*, const char*, int, const struct sockaddr*, int);
static void Perror(const res_state, FILE*, const char*, int);
static int sock_eq(struct sockaddr*, struct sockaddr*);
-void res_pquery(const res_state, const u_char*, int, FILE*);
static int connect_with_timeout(int sock, const struct sockaddr* nsap, socklen_t salen,
const struct timespec timeout);
static int retrying_poll(const int sock, short events, const struct timespec* finish);
@@ -248,8 +266,6 @@
}
/* BIONIC-END */
-static const int niflags = NI_NUMERICHOST | NI_NUMERICSERV;
-
/* Public. */
/* int
@@ -372,7 +388,6 @@
int res_nsend(res_state statp, const u_char* buf, int buflen, u_char* ans, int anssiz) {
int gotsomewhere, terrno, v_circuit, resplen, n;
- char abuf[NI_MAXHOST];
ResolvCacheStatus cache_status = RESOLV_CACHE_UNSUPPORTED;
if (anssiz < HFIXEDSZ) {
@@ -539,6 +554,8 @@
} while (!done);
}
+ [[maybe_unused]] static const int niflags = NI_NUMERICHOST | NI_NUMERICSERV;
+ [[maybe_unused]] char abuf[NI_MAXHOST];
Dprint(((statp->options & RES_DEBUG) &&
getnameinfo(nsap, (socklen_t) nsaplen, abuf, sizeof(abuf), NULL, 0, niflags) ==
0),
@@ -563,18 +580,14 @@
params.max_samples);
}
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", "used send_vc %d\n", n);
- }
+ VLOG << "used send_vc " << n;
if (n < 0) goto fail;
if (n == 0) goto next_ns;
resplen = n;
} else {
/* Use datagrams. */
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", "using send_dg\n");
- }
+ VLOG << "using send_dg";
n = send_dg(statp, ¶ms, buf, buflen, ans, anssiz, &terrno, ns, &v_circuit,
&gotsomewhere, &now, &rcode, &delay);
@@ -587,15 +600,11 @@
params.max_samples);
}
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", "used send_dg %d\n", n);
- }
+ VLOG << "used send_dg " << n;
if (n < 0) goto fail;
if (n == 0) goto next_ns;
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", "time=%ld\n", time(NULL));
- }
+ VLOG << "time=" << time(NULL);
if (v_circuit) goto same_ns;
resplen = n;
}
@@ -719,9 +728,7 @@
msec = 1000; // Use at least 100ms
}
}
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", "using timeout of %d msec\n", msec);
- }
+ VLOG << "using timeout of " << msec << " msec";
struct timespec result;
result.tv_sec = msec / 1000;
@@ -744,9 +751,7 @@
u_short len;
u_char* cp;
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", "using send_vc\n");
- }
+ VLOG << "using send_vc";
nsap = get_nsaddr(statp, (size_t) ns);
nsaplen = get_salen(nsap);
@@ -782,11 +787,11 @@
case EPFNOSUPPORT:
case EAFNOSUPPORT:
Perror(statp, stderr, "socket(vc)", errno);
- return (0);
+ return 0;
default:
*terrno = errno;
Perror(statp, stderr, "socket(vc)", errno);
- return (-1);
+ return -1;
}
}
fchown(statp->_vcsock, AID_DNS, -1);
@@ -912,7 +917,7 @@
}
}
/*
- * If the calling applicating has bailed out of
+ * If the calling application has bailed out of
* a previous call and failed to arrange to have
* the circuit closed or the server has got
* itself confused, then drop the packet and
@@ -953,10 +958,7 @@
if (res != 0) {
struct timespec now = evNowTime();
struct timespec finish = evAddTime(now, timeout);
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", " %d send_vc\n", sock);
- }
-
+ VLOG << sock << " send_vc";
res = retrying_poll(sock, POLLIN | POLLOUT, &finish);
if (res <= 0) {
res = -1;
@@ -964,10 +966,7 @@
}
done:
fcntl(sock, F_SETFL, origflags);
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc",
- " %d connect_with_const timeout returning %d\n", sock, res);
- }
+ VLOG << sock << " connect_with_const timeout returning " << res;
return res;
}
@@ -975,9 +974,7 @@
struct timespec now, timeout;
retry:
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", " %d retrying_poll\n", sock);
- }
+ VLOG << " " << sock << " retrying_poll";
now = evNowTime();
if (evCmpTime(*finish, now) > 0)
@@ -987,18 +984,13 @@
struct pollfd fds = {.fd = sock, .events = events};
int n = ppoll(&fds, 1, &timeout, /*sigmask=*/NULL);
if (n == 0) {
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", " %d retrying_poll timeout\n", sock);
- }
+ VLOG << " " << sock << "retrying_poll timeout";
errno = ETIMEDOUT;
return 0;
}
if (n < 0) {
if (errno == EINTR) goto retry;
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", " %d retrying_poll got error %d\n",
- sock, n);
- }
+ VLOG << " " << sock << " retrying_poll got error " << n;
return n;
}
if (fds.revents & (POLLIN | POLLOUT | POLLERR)) {
@@ -1006,19 +998,11 @@
socklen_t len = sizeof(error);
if (getsockopt(sock, SOL_SOCKET, SO_ERROR, &error, &len) < 0 || error) {
errno = error;
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc",
- " %d retrying_poll dot error2 %d\n", sock, errno);
- }
-
+ VLOG << " " << sock << " retrying_poll dot error2 " << errno;
return -1;
}
}
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", " %d retrying_poll returning %d\n", sock,
- n);
- }
-
+ VLOG << " " << sock << " retrying_poll returning " << n;
return n;
}
@@ -1224,9 +1208,12 @@
static void Aerror(const res_state statp, FILE* file, const char* string, int error,
const struct sockaddr* address, int alen) {
- int save = errno;
+ if (!kVerboseLogging) return;
+
+ const int save = errno;
char hbuf[NI_MAXHOST];
char sbuf[NI_MAXSERV];
+ constexpr int niflags = NI_NUMERICHOST | NI_NUMERICSERV;
if ((statp->options & RES_DEBUG) != 0U) {
if (getnameinfo(address, (socklen_t) alen, hbuf, sizeof(hbuf), sbuf, sizeof(sbuf),
@@ -1242,8 +1229,9 @@
}
static void Perror(const res_state statp, FILE* file, const char* string, int error) {
- int save = errno;
+ if (!kVerboseLogging) return;
+ const int save = errno;
if ((statp->options & RES_DEBUG) != 0U)
fprintf(file, "res_send: %s: %s\n", string, strerror(error));
errno = save;
diff --git a/resolv/res_state.cpp b/resolv/res_state.cpp
index 91e9044..df1528c 100644
--- a/resolv/res_state.cpp
+++ b/resolv/res_state.cpp
@@ -25,6 +25,9 @@
* OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*/
+
+#define LOG_TAG "res_state"
+
#include <arpa/inet.h>
#include <arpa/nameser.h>
#include <netdb.h>
@@ -32,22 +35,13 @@
#include <stdlib.h>
#include <string.h>
#include <sys/types.h>
+#include <unistd.h> /* for gettid() */
+
+#include <android-base/logging.h>
+
#include "resolv_cache.h"
#include "resolv_private.h"
-/* Set to 1 to enable debug traces */
-#define DEBUG 0
-
-#if DEBUG
-#include <async_safe/log.h>
-#include <unistd.h> /* for gettid() */
-#define D(...) async_safe_format_log(ANDROID_LOG_DEBUG, "libc", __VA_ARGS__)
-#else
-#define D(...) \
- do { \
- } while (0)
-#endif
-
typedef struct {
int _h_errno;
// TODO: Have one __res_state per network so we don't have to repopulate frequently.
@@ -80,7 +74,7 @@
static void _res_thread_free(void* _rt) {
_res_thread* rt = (_res_thread*) _rt;
- D("%s: rt=%p for thread=%d", __FUNCTION__, rt, gettid());
+ LOG(VERBOSE) << __func__ << ": rt=" << rt << " for thread=" << gettid();
_res_static_done(rt->_rstatic);
res_ndestroy(rt->_nres);
@@ -106,16 +100,16 @@
return NULL;
}
pthread_setspecific(_res_key, rt);
- D("%s: tid=%d Created new DNS state rt=%p", __FUNCTION__, gettid(), rt);
/* Reset the state, note that res_ninit() can now properly reset
* an existing state without leaking memory.
*/
- D("%s: tid=%d, rt=%p, setting DNS state (options RES_INIT=%d)", __FUNCTION__, gettid(), rt,
- (rt->_nres->options & RES_INIT) != 0);
+ LOG(VERBOSE) << __func__ << ": tid=" << gettid() << ", rt=" << rt
+ << " setting DNS state (options=" << rt->_nres->options << ")";
if (res_ninit(rt->_nres) < 0) {
/* This should not happen */
- D("%s: tid=%d rt=%p, woot, res_ninit() returned < 0", __FUNCTION__, gettid(), rt);
+ LOG(VERBOSE) << __func__ << ": tid=" << gettid() << " rt=" << rt
+ << ", res_ninit() returned < 0";
_res_thread_free(rt);
pthread_setspecific(_res_key, NULL);
return NULL;
diff --git a/resolv/res_stats.cpp b/resolv/res_stats.cpp
index e5a41ab..e2cfd17 100644
--- a/resolv/res_stats.cpp
+++ b/resolv/res_stats.cpp
@@ -14,15 +14,24 @@
* limitations under the License.
*/
+constexpr bool kVerboseLogging = false;
+#define LOG_TAG "res_stats"
+
#include <arpa/nameser.h>
#include <stdbool.h>
#include <string.h>
-#include <async_safe/log.h>
+#include <android-base/logging.h>
#include "resolv_stats.h"
-#define DBG 0
+#define VLOG if (!kVerboseLogging) {} else LOG(INFO)
+
+#ifndef RESOLV_ALLOW_VERBOSE_LOGGING
+static_assert(kVerboseLogging == false,
+ "Verbose logging floods logs at high-rate and exposes privacy-sensitive information. "
+ "Do not enable in release builds.");
+#endif
/* Calculate the round-trip-time from start time t0 and end time t1. */
int _res_stats_calculate_rtt(const struct timespec* t1, const struct timespec* t0) {
@@ -34,9 +43,7 @@
/* Create a sample for calculating server reachability statistics. */
void _res_stats_set_sample(struct __res_sample* sample, time_t now, int rcode, int rtt) {
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_INFO, "libc", "rcode = %d, sec = %d", rcode, rtt);
- }
+ VLOG << __func__ << ": rcode = " << rcode << ", sec = " << rtt;
sample->at = now;
sample->rcode = rcode;
sample->rtt = rtt;
@@ -120,35 +127,26 @@
&rtt_avg, &last_sample_time);
if (successes >= 0 && errors >= 0 && timeouts >= 0) {
int total = successes + errors + timeouts;
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc",
- "NS stats: S %d + E %d + T %d + I %d "
- "= %d, rtt = %d, min_samples = %d\n",
- successes, errors, timeouts, internal_errors, total, rtt_avg,
- params->min_samples);
- }
+ VLOG << "NS stats: S " << successes
+ << " + E " << errors
+ << " + T " << timeouts
+ << " + I " << internal_errors
+ << " = " << total
+ << ", rtt = " << rtt_avg
+ << ", min_samples = " << params->min_samples;
if (total >= params->min_samples && (errors > 0 || timeouts > 0)) {
int success_rate = successes * 100 / total;
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_DEBUG, "libc", "success rate %d%%\n",
- success_rate);
- }
+ VLOG << "success rate " << success_rate;
if (success_rate < params->success_threshold) {
time_t now = time(NULL);
if (now - last_sample_time > params->sample_validity) {
// Note: It might be worth considering to expire old servers after their expiry
// date has been reached, however the code for returning the ring buffer to its
// previous non-circular state would induce additional complexity.
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_INFO, "libc",
- "samples stale, retrying server\n");
- }
+ VLOG << "samples stale, retrying server";
_res_stats_clear_samples(stats);
} else {
- if (DBG) {
- async_safe_format_log(ANDROID_LOG_INFO, "libc",
- "too many resolution errors, ignoring server\n");
- }
+ VLOG << "too many resolution errors, ignoring server";
return 0;
}
}