Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

src: add trace points to dns #21840

Closed
wants to merge 1 commit into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
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) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

does this change cause any external JS API interface change? I guess not.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, this is all internal.

// 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);
}));
}