From c8e586c8591668f73688641867406eabd4b74f6b Mon Sep 17 00:00:00 2001 From: Chin Huang Date: Tue, 10 Jul 2018 22:42:41 +0000 Subject: [PATCH] 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: https://github.com/nodejs/node/pull/19157 PR-URL: https://github.com/nodejs/node/pull/21840 Reviewed-By: Anna Henningsen Reviewed-By: James M Snell Reviewed-By: Gireesh Punathil Reviewed-By: Colin Ihrig Reviewed-By: Joyee Cheung --- src/cares_wrap.cc | 73 ++++++++++++++++++++------ test/internet/test-trace-events-dns.js | 68 ++++++++++++++++++++++++ 2 files changed, 125 insertions(+), 16 deletions(-) create mode 100644 test/internet/test-trace-events-dns.js diff --git a/src/cares_wrap.cc b/src/cares_wrap.cc index 9d3d098734470f..7a119d014f5aa9 100644 --- a/src/cares_wrap.cc +++ b/src/cares_wrap.cc @@ -596,9 +596,10 @@ void ChannelWrap::EnsureServers() { class QueryWrap : public AsyncWrap { public: - QueryWrap(ChannelWrap* channel, Local req_wrap_obj) + QueryWrap(ChannelWrap* channel, Local 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(), @@ -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(this)); } @@ -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); } @@ -730,6 +737,9 @@ class QueryWrap : public AsyncWrap { Context::Scope context_scope(env()->context()); const char* code = ToErrorCodeString(status); Local 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); } @@ -743,6 +753,9 @@ class QueryWrap : public AsyncWrap { } ChannelWrap* channel_; + + private: + const char* trace_name_; }; @@ -1173,7 +1186,7 @@ int ParseSoaReply(Environment* env, class QueryAnyWrap: public QueryWrap { public: QueryAnyWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolveAny") { } int Send(const char* name) override { @@ -1354,7 +1367,7 @@ class QueryAnyWrap: public QueryWrap { class QueryAWrap: public QueryWrap { public: QueryAWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolve4") { } int Send(const char* name) override { @@ -1402,7 +1415,7 @@ class QueryAWrap: public QueryWrap { class QueryAaaaWrap: public QueryWrap { public: QueryAaaaWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolve6") { } int Send(const char* name) override { @@ -1450,7 +1463,7 @@ class QueryAaaaWrap: public QueryWrap { class QueryCnameWrap: public QueryWrap { public: QueryCnameWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolveCname") { } int Send(const char* name) override { @@ -1485,7 +1498,7 @@ class QueryCnameWrap: public QueryWrap { class QueryMxWrap: public QueryWrap { public: QueryMxWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolveMx") { } int Send(const char* name) override { @@ -1520,7 +1533,7 @@ class QueryMxWrap: public QueryWrap { class QueryNsWrap: public QueryWrap { public: QueryNsWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolveNs") { } int Send(const char* name) override { @@ -1555,7 +1568,7 @@ class QueryNsWrap: public QueryWrap { class QueryTxtWrap: public QueryWrap { public: QueryTxtWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolveTxt") { } int Send(const char* name) override { @@ -1589,7 +1602,7 @@ class QueryTxtWrap: public QueryWrap { class QuerySrvWrap: public QueryWrap { public: explicit QuerySrvWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolveSrv") { } int Send(const char* name) override { @@ -1622,7 +1635,7 @@ class QuerySrvWrap: public QueryWrap { class QueryPtrWrap: public QueryWrap { public: explicit QueryPtrWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolvePtr") { } int Send(const char* name) override { @@ -1657,7 +1670,7 @@ class QueryPtrWrap: public QueryWrap { class QueryNaptrWrap: public QueryWrap { public: explicit QueryNaptrWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolveNaptr") { } int Send(const char* name) override { @@ -1691,7 +1704,7 @@ class QueryNaptrWrap: public QueryWrap { class QuerySoaWrap: public QueryWrap { public: QuerySoaWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "resolveSoa") { } int Send(const char* name) override { @@ -1756,7 +1769,7 @@ class QuerySoaWrap: public QueryWrap { class GetHostByAddrWrap: public QueryWrap { public: explicit GetHostByAddrWrap(ChannelWrap* channel, Local req_wrap_obj) - : QueryWrap(channel, req_wrap_obj) { + : QueryWrap(channel, req_wrap_obj, "reverse") { } int Send(const char* name) override { @@ -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, @@ -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 results = Array::New(env->isolate()); auto add = [&] (bool want_ipv4, bool want_ipv6) { @@ -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); @@ -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); @@ -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); @@ -1986,6 +2014,12 @@ void GetAddrInfo(const FunctionCallbackInfo& 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, @@ -2014,6 +2048,10 @@ void GetNameInfo(const FunctionCallbackInfo& 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(&addr), @@ -2145,6 +2183,9 @@ void Cancel(const FunctionCallbackInfo& 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()); } diff --git a/test/internet/test-trace-events-dns.js b/test/internet/test-trace-events-dns.js new file mode 100644 index 00000000000000..3eb787a2caf70e --- /dev/null +++ b/test/internet/test-trace-events-dns.js @@ -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); + })); +}