Skip to content

Commit

Permalink
src: add trace points to dns
Browse files Browse the repository at this point in the history
Add trace points to dns under node.dns.native category.
Emit trace events for dns operations. Use the
nestable async events instead of deprecated ones.
Include test code to verify the trace log. The
trace name is stored as const char* class variable.
The test code is to check each operation in separate
sync processes.

Refs: #19157

PR-URL: #21840
Reviewed-By: Anna Henningsen <[email protected]>
Reviewed-By: James M Snell <[email protected]>
Reviewed-By: Gireesh Punathil <[email protected]>
Reviewed-By: Colin Ihrig <[email protected]>
Reviewed-By: Joyee Cheung <[email protected]>
  • Loading branch information
chinhuang007 authored and targos committed Sep 6, 2018
1 parent 6d6db60 commit c52d67b
Show file tree
Hide file tree
Showing 2 changed files with 125 additions and 16 deletions.
73 changes: 57 additions & 16 deletions src/cares_wrap.cc
Original file line number Diff line number Diff line change
Expand Up @@ -596,9 +596,10 @@ void ChannelWrap::EnsureServers() {

class QueryWrap : public AsyncWrap {
public:
QueryWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
QueryWrap(ChannelWrap* channel, Local<Object> req_wrap_obj, const char* name)
: AsyncWrap(channel->env(), req_wrap_obj, AsyncWrap::PROVIDER_QUERYWRAP),
channel_(channel) {
channel_(channel),
trace_name_(name) {
// Make sure the channel object stays alive during the query lifetime.
req_wrap_obj->Set(env()->context(),
env()->channel_string(),
Expand All @@ -625,6 +626,9 @@ class QueryWrap : public AsyncWrap {
int dnsclass,
int type) {
channel_->EnsureServers();
TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(
TRACING_CATEGORY_NODE2(dns, native), trace_name_, this,
"name", TRACE_STR_COPY(name));
ares_query(channel_->cares_channel(), name, dnsclass, type, Callback,
static_cast<void*>(this));
}
Expand Down Expand Up @@ -721,6 +725,9 @@ class QueryWrap : public AsyncWrap {
extra
};
const int argc = arraysize(argv) - extra.IsEmpty();
TRACE_EVENT_NESTABLE_ASYNC_END0(
TRACING_CATEGORY_NODE2(dns, native), trace_name_, this);

MakeCallback(env()->oncomplete_string(), argc, argv);
}

Expand All @@ -730,6 +737,9 @@ class QueryWrap : public AsyncWrap {
Context::Scope context_scope(env()->context());
const char* code = ToErrorCodeString(status);
Local<Value> arg = OneByteString(env()->isolate(), code);
TRACE_EVENT_NESTABLE_ASYNC_END1(
TRACING_CATEGORY_NODE2(dns, native), trace_name_, this,
"error", status);
MakeCallback(env()->oncomplete_string(), 1, &arg);
}

Expand All @@ -743,6 +753,9 @@ class QueryWrap : public AsyncWrap {
}

ChannelWrap* channel_;

private:
const char* trace_name_;
};


Expand Down Expand Up @@ -1173,7 +1186,7 @@ int ParseSoaReply(Environment* env,
class QueryAnyWrap: public QueryWrap {
public:
QueryAnyWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolveAny") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1354,7 +1367,7 @@ class QueryAnyWrap: public QueryWrap {
class QueryAWrap: public QueryWrap {
public:
QueryAWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolve4") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1402,7 +1415,7 @@ class QueryAWrap: public QueryWrap {
class QueryAaaaWrap: public QueryWrap {
public:
QueryAaaaWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolve6") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1450,7 +1463,7 @@ class QueryAaaaWrap: public QueryWrap {
class QueryCnameWrap: public QueryWrap {
public:
QueryCnameWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolveCname") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1485,7 +1498,7 @@ class QueryCnameWrap: public QueryWrap {
class QueryMxWrap: public QueryWrap {
public:
QueryMxWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolveMx") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1520,7 +1533,7 @@ class QueryMxWrap: public QueryWrap {
class QueryNsWrap: public QueryWrap {
public:
QueryNsWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolveNs") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1555,7 +1568,7 @@ class QueryNsWrap: public QueryWrap {
class QueryTxtWrap: public QueryWrap {
public:
QueryTxtWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolveTxt") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1589,7 +1602,7 @@ class QueryTxtWrap: public QueryWrap {
class QuerySrvWrap: public QueryWrap {
public:
explicit QuerySrvWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolveSrv") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1622,7 +1635,7 @@ class QuerySrvWrap: public QueryWrap {
class QueryPtrWrap: public QueryWrap {
public:
explicit QueryPtrWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolvePtr") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1657,7 +1670,7 @@ class QueryPtrWrap: public QueryWrap {
class QueryNaptrWrap: public QueryWrap {
public:
explicit QueryNaptrWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolveNaptr") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1691,7 +1704,7 @@ class QueryNaptrWrap: public QueryWrap {
class QuerySoaWrap: public QueryWrap {
public:
QuerySoaWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "resolveSoa") {
}

int Send(const char* name) override {
Expand Down Expand Up @@ -1756,7 +1769,7 @@ class QuerySoaWrap: public QueryWrap {
class GetHostByAddrWrap: public QueryWrap {
public:
explicit GetHostByAddrWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
: QueryWrap(channel, req_wrap_obj) {
: QueryWrap(channel, req_wrap_obj, "reverse") {
}

int Send(const char* name) override {
Expand All @@ -1773,6 +1786,11 @@ class GetHostByAddrWrap: public QueryWrap {
return UV_EINVAL; // So errnoException() reports a proper error.
}

TRACE_EVENT_NESTABLE_ASYNC_BEGIN2(
TRACING_CATEGORY_NODE2(dns, native), "reverse", this,
"name", TRACE_STR_COPY(name),
"family", family == AF_INET ? "ipv4" : "ipv6");

ares_gethostbyaddr(channel_->cares_channel(),
address_buffer,
length,
Expand Down Expand Up @@ -1835,8 +1853,10 @@ void AfterGetAddrInfo(uv_getaddrinfo_t* req, int status, struct addrinfo* res) {
Null(env->isolate())
};

uint64_t n = 0;
const bool verbatim = req_wrap->verbatim();

if (status == 0) {
int n = 0;
Local<Array> results = Array::New(env->isolate());

auto add = [&] (bool want_ipv4, bool want_ipv6) {
Expand Down Expand Up @@ -1864,7 +1884,6 @@ void AfterGetAddrInfo(uv_getaddrinfo_t* req, int status, struct addrinfo* res) {
}
};

const bool verbatim = req_wrap->verbatim();
add(true, verbatim);
if (verbatim == false)
add(false, true);
Expand All @@ -1879,6 +1898,10 @@ void AfterGetAddrInfo(uv_getaddrinfo_t* req, int status, struct addrinfo* res) {

uv_freeaddrinfo(res);

TRACE_EVENT_NESTABLE_ASYNC_END2(
TRACING_CATEGORY_NODE2(dns, native), "lookup", req_wrap,
"count", n, "verbatim", verbatim);

// Make the callback into JavaScript
req_wrap->MakeCallback(env->oncomplete_string(), arraysize(argv), argv);

Expand Down Expand Up @@ -1910,6 +1933,11 @@ void AfterGetNameInfo(uv_getnameinfo_t* req,
argv[2] = js_service;
}

TRACE_EVENT_NESTABLE_ASYNC_END2(
TRACING_CATEGORY_NODE2(dns, native), "lookupService", req_wrap,
"hostname", TRACE_STR_COPY(hostname),
"service", TRACE_STR_COPY(service));

// Make the callback into JavaScript
req_wrap->MakeCallback(env->oncomplete_string(), arraysize(argv), argv);

Expand Down Expand Up @@ -1986,6 +2014,12 @@ void GetAddrInfo(const FunctionCallbackInfo<Value>& args) {
hints.ai_socktype = SOCK_STREAM;
hints.ai_flags = flags;

TRACE_EVENT_NESTABLE_ASYNC_BEGIN2(
TRACING_CATEGORY_NODE2(dns, native), "lookup", req_wrap,
"hostname", TRACE_STR_COPY(*hostname),
"family",
family == AF_INET ? "ipv4" : family == AF_INET6 ? "ipv6" : "unspec");

int err = req_wrap->Dispatch(uv_getaddrinfo,
AfterGetAddrInfo,
*hostname,
Expand Down Expand Up @@ -2014,6 +2048,10 @@ void GetNameInfo(const FunctionCallbackInfo<Value>& args) {

GetNameInfoReqWrap* req_wrap = new GetNameInfoReqWrap(env, req_wrap_obj);

TRACE_EVENT_NESTABLE_ASYNC_BEGIN2(
TRACING_CATEGORY_NODE2(dns, native), "lookupService", req_wrap,
"ip", TRACE_STR_COPY(*ip), "port", port);

int err = req_wrap->Dispatch(uv_getnameinfo,
AfterGetNameInfo,
reinterpret_cast<struct sockaddr*>(&addr),
Expand Down Expand Up @@ -2145,6 +2183,9 @@ void Cancel(const FunctionCallbackInfo<Value>& args) {
ChannelWrap* channel;
ASSIGN_OR_RETURN_UNWRAP(&channel, args.Holder());

TRACE_EVENT_INSTANT0(TRACING_CATEGORY_NODE2(dns, native),
"cancel", TRACE_EVENT_SCOPE_THREAD);

ares_cancel(channel->cares_channel());
}

Expand Down
68 changes: 68 additions & 0 deletions test/internet/test-trace-events-dns.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,68 @@
'use strict';
const common = require('../common');
const assert = require('assert');
const cp = require('child_process');
const path = require('path');
const tmpdir = require('../common/tmpdir');
const fs = require('fs');
const util = require('util');

if (!common.isMainThread)
common.skip('process.chdir is not available in Workers');

const traceFile = 'node_trace.1.log';

tmpdir.refresh();
process.chdir(tmpdir.path);

const test_str = 'const dns = require("dns");' +
'const options = {' +
' family: 4,' +
' hints: dns.ADDRCONFIG | dns.V4MAPPED,' +
'};';

const tests = {
'lookup': 'dns.lookup("example.com", options, (err, address, family) => {});',
'lookupService': 'dns.lookupService("127.0.0.1", 22, ' +
'(err, hostname, service) => {});',
'reverse': 'dns.reverse("8.8.8.8", (err, hostnames) => {});',
'resolveAny': 'dns.resolveAny("example.com", (err, res) => {});',
'resolve4': 'dns.resolve4("example.com", (err, res) => {});',
'resolve6': 'dns.resolve6("example.com", (err, res) => {});',
'resolveCname': 'dns.resolveCname("example.com", (err, res) => {});',
'resolveMx': 'dns.resolveMx("example.com", (err, res) => {});',
'resolveNs': 'dns.resolveNs("example.com", (err, res) => {});',
'resolveTxt': 'dns.resolveTxt("example.com", (err, res) => {});',
'resolveSrv': 'dns.resolveSrv("example.com", (err, res) => {});',
'resolvePtr': 'dns.resolvePtr("example.com", (err, res) => {});',
'resolveNaptr': 'dns.resolveNaptr("example.com", (err, res) => {});',
'resolveSoa': 'dns.resolveSoa("example.com", (err, res) => {});'
};

for (const tr in tests) {
const proc = cp.spawnSync(process.execPath,
[ '--trace-event-categories',
'node.dns.native',
'-e',
test_str + tests[tr]
],
{ encoding: 'utf8' });

// Make sure the operation is successful.
assert.strictEqual(proc.status, 0, `${tr}:\n${util.inspect(proc)}`);

const file = path.join(tmpdir.path, traceFile);

// Confirm that trace log file is created.
assert(common.fileExists(file));
const data = fs.readFileSync(file);
const traces = JSON.parse(data.toString()).traceEvents
.filter((trace) => trace.cat !== '__metadata');

assert(traces.length > 0);

// DNS native trace events should be generated.
assert(traces.some((trace) => {
return (trace.name === tr && trace.pid === proc.pid);
}));
}

0 comments on commit c52d67b

Please sign in to comment.