Skip to content

Commit c8e586c

Browse files
chinhuang007targos
chinhuang007
authored and
targos
committed
src: add trace points to dns
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]>
1 parent 11c9698 commit c8e586c

File tree

2 files changed

+125
-16
lines changed

2 files changed

+125
-16
lines changed

‎src/cares_wrap.cc‎

Lines changed: 57 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -596,9 +596,10 @@ void ChannelWrap::EnsureServers() {
596596

597597
class QueryWrap : public AsyncWrap {
598598
public:
599-
QueryWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
599+
QueryWrap(ChannelWrap* channel, Local<Object> req_wrap_obj, const char* name)
600600
: AsyncWrap(channel->env(), req_wrap_obj, AsyncWrap::PROVIDER_QUERYWRAP),
601-
channel_(channel) {
601+
channel_(channel),
602+
trace_name_(name) {
602603
// Make sure the channel object stays alive during the query lifetime.
603604
req_wrap_obj->Set(env()->context(),
604605
env()->channel_string(),
@@ -625,6 +626,9 @@ class QueryWrap : public AsyncWrap {
625626
int dnsclass,
626627
int type) {
627628
channel_->EnsureServers();
629+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(
630+
TRACING_CATEGORY_NODE2(dns, native), trace_name_, this,
631+
"name", TRACE_STR_COPY(name));
628632
ares_query(channel_->cares_channel(), name, dnsclass, type, Callback,
629633
static_cast<void*>(this));
630634
}
@@ -721,6 +725,9 @@ class QueryWrap : public AsyncWrap {
721725
extra
722726
};
723727
const int argc = arraysize(argv) - extra.IsEmpty();
728+
TRACE_EVENT_NESTABLE_ASYNC_END0(
729+
TRACING_CATEGORY_NODE2(dns, native), trace_name_, this);
730+
724731
MakeCallback(env()->oncomplete_string(), argc, argv);
725732
}
726733

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

@@ -743,6 +753,9 @@ class QueryWrap : public AsyncWrap {
743753
}
744754

745755
ChannelWrap* channel_;
756+
757+
private:
758+
const char* trace_name_;
746759
};
747760

748761

@@ -1173,7 +1186,7 @@ int ParseSoaReply(Environment* env,
11731186
class QueryAnyWrap: public QueryWrap {
11741187
public:
11751188
QueryAnyWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1176-
: QueryWrap(channel, req_wrap_obj) {
1189+
: QueryWrap(channel, req_wrap_obj, "resolveAny") {
11771190
}
11781191

11791192
int Send(const char* name) override {
@@ -1354,7 +1367,7 @@ class QueryAnyWrap: public QueryWrap {
13541367
class QueryAWrap: public QueryWrap {
13551368
public:
13561369
QueryAWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1357-
: QueryWrap(channel, req_wrap_obj) {
1370+
: QueryWrap(channel, req_wrap_obj, "resolve4") {
13581371
}
13591372

13601373
int Send(const char* name) override {
@@ -1402,7 +1415,7 @@ class QueryAWrap: public QueryWrap {
14021415
class QueryAaaaWrap: public QueryWrap {
14031416
public:
14041417
QueryAaaaWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1405-
: QueryWrap(channel, req_wrap_obj) {
1418+
: QueryWrap(channel, req_wrap_obj, "resolve6") {
14061419
}
14071420

14081421
int Send(const char* name) override {
@@ -1450,7 +1463,7 @@ class QueryAaaaWrap: public QueryWrap {
14501463
class QueryCnameWrap: public QueryWrap {
14511464
public:
14521465
QueryCnameWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1453-
: QueryWrap(channel, req_wrap_obj) {
1466+
: QueryWrap(channel, req_wrap_obj, "resolveCname") {
14541467
}
14551468

14561469
int Send(const char* name) override {
@@ -1485,7 +1498,7 @@ class QueryCnameWrap: public QueryWrap {
14851498
class QueryMxWrap: public QueryWrap {
14861499
public:
14871500
QueryMxWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1488-
: QueryWrap(channel, req_wrap_obj) {
1501+
: QueryWrap(channel, req_wrap_obj, "resolveMx") {
14891502
}
14901503

14911504
int Send(const char* name) override {
@@ -1520,7 +1533,7 @@ class QueryMxWrap: public QueryWrap {
15201533
class QueryNsWrap: public QueryWrap {
15211534
public:
15221535
QueryNsWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1523-
: QueryWrap(channel, req_wrap_obj) {
1536+
: QueryWrap(channel, req_wrap_obj, "resolveNs") {
15241537
}
15251538

15261539
int Send(const char* name) override {
@@ -1555,7 +1568,7 @@ class QueryNsWrap: public QueryWrap {
15551568
class QueryTxtWrap: public QueryWrap {
15561569
public:
15571570
QueryTxtWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1558-
: QueryWrap(channel, req_wrap_obj) {
1571+
: QueryWrap(channel, req_wrap_obj, "resolveTxt") {
15591572
}
15601573

15611574
int Send(const char* name) override {
@@ -1589,7 +1602,7 @@ class QueryTxtWrap: public QueryWrap {
15891602
class QuerySrvWrap: public QueryWrap {
15901603
public:
15911604
explicit QuerySrvWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1592-
: QueryWrap(channel, req_wrap_obj) {
1605+
: QueryWrap(channel, req_wrap_obj, "resolveSrv") {
15931606
}
15941607

15951608
int Send(const char* name) override {
@@ -1622,7 +1635,7 @@ class QuerySrvWrap: public QueryWrap {
16221635
class QueryPtrWrap: public QueryWrap {
16231636
public:
16241637
explicit QueryPtrWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1625-
: QueryWrap(channel, req_wrap_obj) {
1638+
: QueryWrap(channel, req_wrap_obj, "resolvePtr") {
16261639
}
16271640

16281641
int Send(const char* name) override {
@@ -1657,7 +1670,7 @@ class QueryPtrWrap: public QueryWrap {
16571670
class QueryNaptrWrap: public QueryWrap {
16581671
public:
16591672
explicit QueryNaptrWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1660-
: QueryWrap(channel, req_wrap_obj) {
1673+
: QueryWrap(channel, req_wrap_obj, "resolveNaptr") {
16611674
}
16621675

16631676
int Send(const char* name) override {
@@ -1691,7 +1704,7 @@ class QueryNaptrWrap: public QueryWrap {
16911704
class QuerySoaWrap: public QueryWrap {
16921705
public:
16931706
QuerySoaWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1694-
: QueryWrap(channel, req_wrap_obj) {
1707+
: QueryWrap(channel, req_wrap_obj, "resolveSoa") {
16951708
}
16961709

16971710
int Send(const char* name) override {
@@ -1756,7 +1769,7 @@ class QuerySoaWrap: public QueryWrap {
17561769
class GetHostByAddrWrap: public QueryWrap {
17571770
public:
17581771
explicit GetHostByAddrWrap(ChannelWrap* channel, Local<Object> req_wrap_obj)
1759-
: QueryWrap(channel, req_wrap_obj) {
1772+
: QueryWrap(channel, req_wrap_obj, "reverse") {
17601773
}
17611774

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

1789+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN2(
1790+
TRACING_CATEGORY_NODE2(dns, native), "reverse", this,
1791+
"name", TRACE_STR_COPY(name),
1792+
"family", family == AF_INET ? "ipv4" : "ipv6");
1793+
17761794
ares_gethostbyaddr(channel_->cares_channel(),
17771795
address_buffer,
17781796
length,
@@ -1835,8 +1853,10 @@ void AfterGetAddrInfo(uv_getaddrinfo_t* req, int status, struct addrinfo* res) {
18351853
Null(env->isolate())
18361854
};
18371855

1856+
uint64_t n = 0;
1857+
const bool verbatim = req_wrap->verbatim();
1858+
18381859
if (status == 0) {
1839-
int n = 0;
18401860
Local<Array> results = Array::New(env->isolate());
18411861

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

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

18801899
uv_freeaddrinfo(res);
18811900

1901+
TRACE_EVENT_NESTABLE_ASYNC_END2(
1902+
TRACING_CATEGORY_NODE2(dns, native), "lookup", req_wrap,
1903+
"count", n, "verbatim", verbatim);
1904+
18821905
// Make the callback into JavaScript
18831906
req_wrap->MakeCallback(env->oncomplete_string(), arraysize(argv), argv);
18841907

@@ -1910,6 +1933,11 @@ void AfterGetNameInfo(uv_getnameinfo_t* req,
19101933
argv[2] = js_service;
19111934
}
19121935

1936+
TRACE_EVENT_NESTABLE_ASYNC_END2(
1937+
TRACING_CATEGORY_NODE2(dns, native), "lookupService", req_wrap,
1938+
"hostname", TRACE_STR_COPY(hostname),
1939+
"service", TRACE_STR_COPY(service));
1940+
19131941
// Make the callback into JavaScript
19141942
req_wrap->MakeCallback(env->oncomplete_string(), arraysize(argv), argv);
19151943

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

2017+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN2(
2018+
TRACING_CATEGORY_NODE2(dns, native), "lookup", req_wrap,
2019+
"hostname", TRACE_STR_COPY(*hostname),
2020+
"family",
2021+
family == AF_INET ? "ipv4" : family == AF_INET6 ? "ipv6" : "unspec");
2022+
19892023
int err = req_wrap->Dispatch(uv_getaddrinfo,
19902024
AfterGetAddrInfo,
19912025
*hostname,
@@ -2014,6 +2048,10 @@ void GetNameInfo(const FunctionCallbackInfo<Value>& args) {
20142048

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

2051+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN2(
2052+
TRACING_CATEGORY_NODE2(dns, native), "lookupService", req_wrap,
2053+
"ip", TRACE_STR_COPY(*ip), "port", port);
2054+
20172055
int err = req_wrap->Dispatch(uv_getnameinfo,
20182056
AfterGetNameInfo,
20192057
reinterpret_cast<struct sockaddr*>(&addr),
@@ -2145,6 +2183,9 @@ void Cancel(const FunctionCallbackInfo<Value>& args) {
21452183
ChannelWrap* channel;
21462184
ASSIGN_OR_RETURN_UNWRAP(&channel, args.Holder());
21472185

2186+
TRACE_EVENT_INSTANT0(TRACING_CATEGORY_NODE2(dns, native),
2187+
"cancel", TRACE_EVENT_SCOPE_THREAD);
2188+
21482189
ares_cancel(channel->cares_channel());
21492190
}
21502191

‎test/internet/test-trace-events-dns.js‎

Lines changed: 68 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,68 @@
1+
'use strict';
2+
const common = require('../common');
3+
const assert = require('assert');
4+
const cp = require('child_process');
5+
const path = require('path');
6+
const tmpdir = require('../common/tmpdir');
7+
const fs = require('fs');
8+
const util = require('util');
9+
10+
if (!common.isMainThread)
11+
common.skip('process.chdir is not available in Workers');
12+
13+
const traceFile = 'node_trace.1.log';
14+
15+
tmpdir.refresh();
16+
process.chdir(tmpdir.path);
17+
18+
const test_str = 'const dns = require("dns");' +
19+
'const options = {' +
20+
' family: 4,' +
21+
' hints: dns.ADDRCONFIG | dns.V4MAPPED,' +
22+
'};';
23+
24+
const tests = {
25+
'lookup': 'dns.lookup("example.com", options, (err, address, family) => {});',
26+
'lookupService': 'dns.lookupService("127.0.0.1", 22, ' +
27+
'(err, hostname, service) => {});',
28+
'reverse': 'dns.reverse("8.8.8.8", (err, hostnames) => {});',
29+
'resolveAny': 'dns.resolveAny("example.com", (err, res) => {});',
30+
'resolve4': 'dns.resolve4("example.com", (err, res) => {});',
31+
'resolve6': 'dns.resolve6("example.com", (err, res) => {});',
32+
'resolveCname': 'dns.resolveCname("example.com", (err, res) => {});',
33+
'resolveMx': 'dns.resolveMx("example.com", (err, res) => {});',
34+
'resolveNs': 'dns.resolveNs("example.com", (err, res) => {});',
35+
'resolveTxt': 'dns.resolveTxt("example.com", (err, res) => {});',
36+
'resolveSrv': 'dns.resolveSrv("example.com", (err, res) => {});',
37+
'resolvePtr': 'dns.resolvePtr("example.com", (err, res) => {});',
38+
'resolveNaptr': 'dns.resolveNaptr("example.com", (err, res) => {});',
39+
'resolveSoa': 'dns.resolveSoa("example.com", (err, res) => {});'
40+
};
41+
42+
for (const tr in tests) {
43+
const proc = cp.spawnSync(process.execPath,
44+
[ '--trace-event-categories',
45+
'node.dns.native',
46+
'-e',
47+
test_str + tests[tr]
48+
],
49+
{ encoding: 'utf8' });
50+
51+
// Make sure the operation is successful.
52+
assert.strictEqual(proc.status, 0, `${tr}:\n${util.inspect(proc)}`);
53+
54+
const file = path.join(tmpdir.path, traceFile);
55+
56+
// Confirm that trace log file is created.
57+
assert(common.fileExists(file));
58+
const data = fs.readFileSync(file);
59+
const traces = JSON.parse(data.toString()).traceEvents
60+
.filter((trace) => trace.cat !== '__metadata');
61+
62+
assert(traces.length > 0);
63+
64+
// DNS native trace events should be generated.
65+
assert(traces.some((trace) => {
66+
return (trace.name === tr && trace.pid === proc.pid);
67+
}));
68+
}

0 commit comments

Comments
 (0)