diff --git a/doc/api/diagnostics_channel.md b/doc/api/diagnostics_channel.md index e5ace9abcfdd..5635216e5e99 100644 --- a/doc/api/diagnostics_channel.md +++ b/doc/api/diagnostics_channel.md @@ -1562,6 +1562,87 @@ passed to `console.warn()`. Emitted when `console.error()` is called. Receives and array of the arguments passed to `console.error()`. +#### Filesystem + +> Stability: 1 - Experimental + +These channels are emitted for file system operations performed through +`node:fs` and `node:fs/promises`. They form a [`TracingChannel`][] family named +`fs.operation`, so subscribers can use +[`diagnostics_channel.tracingChannel()`][] to subscribe to all events at once: + +```mjs +import diagnostics_channel from 'node:diagnostics_channel'; + +const channel = diagnostics_channel.tracingChannel('fs.operation'); +channel.subscribe({ + start: (event) => console.log('start', event), + end: (event) => console.log('end', event), + error: (event) => console.log('error', event), +}); +``` + +The events are published from the internal file system implementation, so they +are observed for every public `fs` operation regardless of whether the +function reference was captured before subscribing or whether the operation +uses the callback, promise, or synchronous API. + +Each event carries an object with the following common fields: + +* `operation` {string} A stable operation name, such as `open`, `read`, + `write`, `stat`, `readdir`, or `realpath`. +* `api` {string} The API that performed the operation: `'sync'`, `'callback'`, + or `'promise'`. +* `path` {string|undefined} The path argument for path-based operations, or + the source path for operations with a destination. +* `dest` {string|undefined} The destination argument for operations that + accept one, such as `rename`, `link`, `symlink`, or `copyFile`. +* `fd` {number|undefined} The file descriptor for operations that operate on + an existing file descriptor, such as `read`, `write`, `fsync`, or `close`. + +Large read/write buffers are not copied into the event payload. The `start` +and `asyncStart` events carry no `result` or `error`; the `end` and `asyncEnd` +events carry the `result` of the operation, and the `error` event carries the +`error`, following the [TracingChannel Channels][] conventions. + +Operations performed through streams (`fs.createReadStream` and +`fs.createWriteStream`) and most `FileHandle` methods are not covered by this +channel family, and may not emit the full set of events. + +##### Event: `'tracing:fs.operation:start'` + +Emitted synchronously when an operation begins, before the operation is +submitted. For synchronous operations this is followed by `end` (or `error`); +for asynchronous operations it is followed by `end` and then `asyncStart`/ +`asyncEnd` (or `error`). + +##### Event: `'tracing:fs.operation:end'` + +* `result` {any} The result of the operation. + +Emitted when the operation completes. For synchronous operations this carries +the operation `result`; for asynchronous operations it is emitted when the +operation is submitted and carries no `result` (the `result` is delivered on +the `asyncEnd` event). + +##### Event: `'tracing:fs.operation:asyncStart'` + +Emitted when the asynchronous work for an operation begins (when the +completion callback is invoked). + +##### Event: `'tracing:fs.operation:asyncEnd'` + +* `result` {any} The result of the operation. + +Emitted when the asynchronous work for an operation completes, carrying the +operation `result`. + +##### Event: `'tracing:fs.operation:error'` + +* `error` {Error} The error that caused the operation to fail. + +Emitted when an operation fails. + #### HTTP > Stability: 1 - Experimental diff --git a/src/env_properties.h b/src/env_properties.h index f54efa36b6df..44697b56816a 100644 --- a/src/env_properties.h +++ b/src/env_properties.h @@ -87,6 +87,7 @@ V(allow_bare_named_params_string, "allowBareNamedParameters") \ V(allow_unknown_named_params_string, "allowUnknownNamedParameters") \ V(alpn_callback_string, "ALPNCallback") \ + V(api_string, "api") \ V(args_string, "args") \ V(arguments_string, "arguments") \ V(async_ids_stack_string, "async_ids_stack") \ @@ -293,6 +294,7 @@ V(onwrite_string, "onwrite") \ V(ongracefulclosecomplete_string, "ongracefulclosecomplete") \ V(openssl_error_stack, "opensslErrorStack") \ + V(operation_string, "operation") \ V(operationerror_string, "OperationError") \ V(options_string, "options") \ V(original_string, "original") \ diff --git a/src/node_file-inl.h b/src/node_file-inl.h index e0fc86bedc74..c5511df5c12b 100644 --- a/src/node_file-inl.h +++ b/src/node_file-inl.h @@ -220,6 +220,7 @@ FSReqPromise::FSReqPromise(BindingData* binding_data, template void FSReqPromise::Reject(v8::Local reject) { finished_ = true; + PublishFSOpCompletionEvent(this, FSOperationChannel::kError, "error", reject); v8::HandleScope scope(env()->isolate()); InternalCallbackScope callback_scope(this); v8::Local value; @@ -238,6 +239,8 @@ void FSReqPromise::Reject(v8::Local reject) { template void FSReqPromise::Resolve(v8::Local value) { finished_ = true; + PublishFSOpCompletionEvent(this, FSOperationChannel::kAsyncEnd, "result", + value); v8::HandleScope scope(env()->isolate()); InternalCallbackScope callback_scope(this); v8::Local val; @@ -303,6 +306,7 @@ FSReqBase* GetReqWrap(const v8::FunctionCallbackInfo& args, result = FSReqPromise::New(binding_data, use_bigint); } + result->set_is_promise(true); } } if (result != nullptr) { @@ -320,6 +324,15 @@ FSReqBase* AsyncDestCall(Environment* env, FSReqBase* req_wrap, Func fn, Args... fn_args) { CHECK_NOT_NULL(req_wrap); req_wrap->Init(syscall, dest, len, enc); + BindingData* binding = req_wrap->binding_data(); + const char* api = req_wrap->is_promise() ? "promise" : "callback"; + std::string dest_str; + if (binding != nullptr) { + if (req_wrap->data() != nullptr) dest_str = req_wrap->data(); + PublishFSOperationEvent(binding, env, FSOperationChannel::kStart, syscall, + api, std::string(), dest_str, -1, nullptr, + v8::Local()); + } int err = req_wrap->Dispatch(fn, fn_args..., after); if (err < 0) { uv_fs_t* uv_req = req_wrap->req(); @@ -327,6 +340,16 @@ FSReqBase* AsyncDestCall(Environment* env, FSReqBase* req_wrap, uv_req->path = nullptr; after(uv_req); // after may delete req_wrap if there is an error req_wrap = nullptr; + } else if (binding != nullptr) { + std::string path; + if (req_wrap->req()->path != nullptr) path = req_wrap->req()->path; + int fd = -1; + if (OperationUsesFd(req_wrap->req()->fs_type)) fd = req_wrap->req()->file; + req_wrap->set_op_path(path); + req_wrap->set_fd(fd); + PublishFSOperationEvent(binding, env, FSOperationChannel::kEnd, syscall, + api, path, dest_str, fd, nullptr, + v8::Local()); } return req_wrap; } @@ -381,7 +404,43 @@ int SyncCallAndThrowIf(Predicate should_throw, Func fn, Args... args) { env->PrintSyncTrace(); + BindingData* binding = Realm::GetBindingData(env->context()); + std::string path; + std::string dest; + if (binding != nullptr) { + if (req_wrap->path_p != nullptr) path = req_wrap->path_p; + if (req_wrap->dest_p != nullptr) dest = req_wrap->dest_p; + PublishFSOperationEvent(binding, env, FSOperationChannel::kStart, + req_wrap->syscall_p, "sync", path, dest, -1, + nullptr, v8::Local()); + } int result = fn(nullptr, &(req_wrap->req), args..., nullptr); + if (binding != nullptr) { + int fd = -1; + if (OperationUsesFd(req_wrap->req.fs_type)) fd = req_wrap->req.file; + if (should_throw(result)) { + v8::Local error = UVException(env->isolate(), + result, + req_wrap->syscall_p, + nullptr, + req_wrap->path_p, + req_wrap->dest_p); + PublishFSOperationEvent(binding, env, FSOperationChannel::kError, + req_wrap->syscall_p, "sync", path, dest, fd, + "error", error); + } else { + PublishFSOperationEvent(binding, + env, + FSOperationChannel::kEnd, + req_wrap->syscall_p, + "sync", + path, + dest, + fd, + "result", + v8::Integer::New(env->isolate(), result)); + } + } if (should_throw(result)) { env->ThrowUVException(result, req_wrap->syscall_p, diff --git a/src/node_file.cc b/src/node_file.cc index ae0d9f34f8e1..d9daaeb62c15 100644 --- a/src/node_file.cc +++ b/src/node_file.cc @@ -87,6 +87,121 @@ using v8::TryCatch; using v8::Undefined; using v8::Value; +// Built-in tracing channel names for filesystem operations, one per +// FSOperationChannel in node_file.h. +const char* const kFSOperationChannelNames[kNumFSOperationChannels] = { + "tracing:fs.operation:start", + "tracing:fs.operation:end", + "tracing:fs.operation:asyncStart", + "tracing:fs.operation:asyncEnd", + "tracing:fs.operation:error", +}; + +void PublishFSOperationEvent(BindingData* binding, + Environment* env, + FSOperationChannel channel, + const char* operation, + const char* api, + const std::string& path, + const std::string& dest, + int fd, + const char* value_key, + Local value) { + const size_t index = static_cast(channel); + CHECK_LT(index, kNumFSOperationChannels); + diagnostics_channel::Channel* ch = binding->fs_op_channels_[index]; + if (ch == nullptr) { + ch = diagnostics_channel::Channel::Get( + env, kFSOperationChannelNames[index]); + binding->fs_op_channels_[index] = ch; + } + if (ch == nullptr || !ch->HasSubscribers()) { + return; + } + + Isolate* isolate = env->isolate(); + HandleScope scope(isolate); + Local context = env->context(); + Local obj = Object::New(isolate); + obj->Set(context, + env->operation_string(), + String::NewFromUtf8(isolate, operation).ToLocalChecked()) + .Check(); + obj->Set(context, env->api_string(), + String::NewFromUtf8(isolate, api).ToLocalChecked()) + .Check(); + if (!path.empty()) { + obj->Set(context, + env->path_string(), + String::NewFromUtf8(isolate, + path.data(), + v8::NewStringType::kNormal, + static_cast(path.size())) + .ToLocalChecked()) + .Check(); + } + if (!dest.empty()) { + obj->Set(context, + env->dest_string(), + String::NewFromUtf8(isolate, + dest.data(), + v8::NewStringType::kNormal, + static_cast(dest.size())) + .ToLocalChecked()) + .Check(); + } + if (fd != -1) { + obj->Set(context, env->fd_string(), Integer::New(isolate, fd)).Check(); + } + if (value_key != nullptr && !value.IsEmpty()) { + obj->Set(context, OneByteString(isolate, value_key), value).Check(); + } + ch->Publish(env, obj); +} + +void PublishFSOpCompletionEvent(FSReqBase* req_wrap, + FSOperationChannel channel, + const char* value_key, + Local value) { + BindingData* binding = req_wrap->binding_data(); + if (binding == nullptr) return; + const char* api = req_wrap->is_promise() ? "promise" : "callback"; + std::string dest; + if (req_wrap->data() != nullptr) dest = req_wrap->data(); + PublishFSOperationEvent(binding, + req_wrap->env(), + channel, + req_wrap->syscall(), + api, + req_wrap->op_path(), + dest, + req_wrap->fd(), + value_key, + value); +} + +// Returns true if the libuv fs request type operates on an existing file +// descriptor (as opposed to taking a path). These are the request types whose +// `file` field holds the input descriptor. +bool OperationUsesFd(uv_fs_type fs_type) { + switch (fs_type) { + case UV_FS_CLOSE: + case UV_FS_READ: + case UV_FS_WRITE: + case UV_FS_FSTAT: + case UV_FS_FTRUNCATE: + case UV_FS_FDATASYNC: + case UV_FS_FSYNC: + case UV_FS_FUTIME: + case UV_FS_FCHMOD: + case UV_FS_FCHOWN: + case UV_FS_SENDFILE: + return true; + default: + return false; + } +} + #ifndef S_ISDIR #define S_ISDIR(mode) (((mode)&S_IFMT) == S_IFDIR) #endif @@ -221,6 +336,7 @@ FSReqBase::~FSReqBase() = default; void FSReqBase::MemoryInfo(MemoryTracker* tracker) const { tracker->TrackField("continuation_data", continuation_data_); + tracker->TrackField("op_path", op_path_); } // The FileHandle object wraps a file descriptor and will close it on garbage @@ -728,6 +844,7 @@ int FileHandle::DoShutdown(ShutdownWrap* req_wrap) { } void FSReqCallback::Reject(Local reject) { + PublishFSOpCompletionEvent(this, FSOperationChannel::kError, "error", reject); MakeCallback(env()->oncomplete_string(), 1, &reject); } @@ -740,6 +857,8 @@ void FSReqCallback::ResolveStatFs(const uv_statfs_t* stat) { } void FSReqCallback::Resolve(Local value) { + PublishFSOpCompletionEvent(this, FSOperationChannel::kAsyncEnd, "result", + value); Local argv[2]{Null(env()->isolate()), value}; MakeCallback(env()->oncomplete_string(), value->IsUndefined() ? 1 : arraysize(argv), @@ -762,6 +881,10 @@ FSReqAfterScope::FSReqAfterScope(FSReqBase* wrap, uv_fs_t* req) handle_scope_(wrap->env()->isolate()), context_scope_(wrap->env()->context()) { CHECK_EQ(wrap_->req(), req); + // The async work for the operation has completed; the continuation window + // begins here. + PublishFSOpCompletionEvent(wrap, FSOperationChannel::kAsyncStart, nullptr, + Local()); } FSReqAfterScope::~FSReqAfterScope() { diff --git a/src/node_file.h b/src/node_file.h index 17f3b4203c8e..6992359f0a5b 100644 --- a/src/node_file.h +++ b/src/node_file.h @@ -3,8 +3,10 @@ #if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS +#include #include #include "aliased_buffer.h" +#include "node_diagnostics_channel.h" #include "node_messaging.h" #include "node_snapshotable.h" #include "stream_base.h" @@ -56,6 +58,52 @@ enum class FsStatFsOffset { constexpr size_t kFsStatFsBufferLength = static_cast(FsStatFsOffset::kFsStatFsFieldsNumber); +// Built-in diagnostics channel family for filesystem operations. +// The channel names follow the tracing channel convention so that subscribers +// can use `diagnostics_channel.tracingChannel('fs.operation')` to subscribe to +// all events, or subscribe to individual channels by name. +enum class FSOperationChannel { + kStart, + kEnd, + kAsyncStart, + kAsyncEnd, + kError, + kChannelCount, +}; + +static constexpr size_t kNumFSOperationChannels = + static_cast(FSOperationChannel::kChannelCount); + +class FSReqBase; +class BindingData; + +// The shared event payload for fs operation channels. Fields are set only when +// applicable: `path`/`dest` for path-based operations, `fd` for operations that +// operate on an existing file descriptor, and `result`/`error` on the matching +// end/error channels, following the TracingChannel conventions. +void PublishFSOperationEvent(BindingData* binding, + Environment* env, + FSOperationChannel channel, + const char* operation, + const char* api, + const std::string& path, + const std::string& dest, + int fd, + const char* value_key, + v8::Local value); + +// Publishes a completion event (asyncStart/asyncEnd/error) for an in-flight +// async fs operation, deriving the event context from the request wrap. +void PublishFSOpCompletionEvent(FSReqBase* req_wrap, + FSOperationChannel channel, + const char* value_key, + v8::Local value); + +// Returns true if the libuv fs request type operates on an existing file +// descriptor (as opposed to taking a path), i.e. its `file` field holds the +// input descriptor. +bool OperationUsesFd(uv_fs_type fs_type); + class BindingData : public SnapshotableObject { public: struct InternalFieldInfo : public node::InternalFieldInfoBase { @@ -81,6 +129,11 @@ class BindingData : public SnapshotableObject { AliasedFloat64Array statfs_field_array; AliasedBigInt64Array statfs_field_bigint_array; + // Lazily cached built-in fs operation channels. Null until first used, and + // re-fetched after snapshot deserialization (fresh BindingData). + std::array + fs_op_channels_{}; + std::vector> file_handle_read_wrap_freelist; SERIALIZABLE_OBJECT_METHODS() @@ -164,6 +217,16 @@ class FSReqBase : public ReqWrap { bool is_plain_open() const { return is_plain_open_; } bool with_file_types() const { return with_file_types_; } + // Whether this request was created for the promise-based fs API. + bool is_promise() const { return is_promise_; } + void set_is_promise(bool value) { is_promise_ = value; } + // Path and file descriptor captured at dispatch time, used to publish + // fs operation tracing events even after the uv request is cleaned up. + const std::string& op_path() const { return op_path_; } + void set_op_path(std::string value) { op_path_ = std::move(value); } + int fd() const { return fd_; } + void set_fd(int value) { fd_ = value; } + void set_is_plain_open(bool value) { is_plain_open_ = value; } void set_with_file_types(bool value) { with_file_types_ = value; } @@ -192,6 +255,9 @@ class FSReqBase : public ReqWrap { bool use_bigint_ = false; bool is_plain_open_ = false; bool with_file_types_ = false; + bool is_promise_ = false; + std::string op_path_; + int fd_ = -1; const char* syscall_ = nullptr; BaseObjectPtr binding_data_; diff --git a/test/parallel/test-diagnostics-channel-fs.js b/test/parallel/test-diagnostics-channel-fs.js new file mode 100644 index 000000000000..f225b8eb3ad3 --- /dev/null +++ b/test/parallel/test-diagnostics-channel-fs.js @@ -0,0 +1,104 @@ +'use strict'; + +const common = require('../common'); +const assert = require('node:assert'); +const dc = require('node:diagnostics_channel'); +const fs = require('node:fs'); +const fsp = require('node:fs/promises'); +const tmpdir = require('node:os').tmpdir(); +const { join } = require('node:path'); + +const events = []; +const eventTypes = ['start', 'end', 'asyncStart', 'asyncEnd', 'error']; +for (const type of eventTypes) { + dc.channel(`tracing:fs.operation:${type}`).subscribe((event) => { + events.push({ type, event }); + }); +} + +const target = join(tmpdir, `node-test-diagnostics-channel-fs-${process.pid}-${Date.now()}`); +const source = join(tmpdir, `node-test-diagnostics-channel-fs-src-${process.pid}-${Date.now()}`); + +function byOperation(operation) { + return events.filter((e) => e.event.operation === operation); +} + +// Sync operations publish start/end (or error) with api: 'sync'. +fs.writeFileSync(target, 'hello'); + +const openSync = byOperation('open'); +assert.ok(openSync.length >= 2, 'expected open start/end for writeFileSync'); +const openStart = openSync[0]; +const openEnd = openSync[openSync.length - 1]; +assert.strictEqual(openStart.type, 'start'); +assert.strictEqual(openStart.event.api, 'sync'); +assert.strictEqual(openStart.event.path, target); +assert.strictEqual(openStart.event.operation, 'open'); +assert.strictEqual(openEnd.type, 'end'); +assert.strictEqual(openEnd.event.api, 'sync'); +assert.strictEqual(openEnd.event.path, target); +assert.strictEqual(typeof openEnd.event.result, 'number'); // the returned fd + +// Callback operations publish start, end, asyncStart, asyncEnd with api. +fs.readFile(target, 'utf8', common.mustSucceed((data) => { + assert.strictEqual(data, 'hello'); + + const readEvents = byOperation('read'); + assert.ok(readEvents.length >= 4, 'expected read start/end/asyncStart/asyncEnd'); + const readStart = readEvents[0]; + const readEnd = readEvents[1]; + const readAsyncStart = readEvents[2]; + const readAsyncEnd = readEvents[readEvents.length - 1]; + + assert.strictEqual(readStart.type, 'start'); + assert.strictEqual(readStart.event.api, 'callback'); + assert.strictEqual(readStart.event.fd, undefined); + assert.strictEqual(readEnd.type, 'end'); + assert.strictEqual(readEnd.event.api, 'callback'); + assert.strictEqual(typeof readEnd.event.fd, 'number'); + assert.strictEqual(readEnd.event.result, undefined); + assert.strictEqual(readAsyncStart.type, 'asyncStart'); + assert.strictEqual(readAsyncStart.event.api, 'callback'); + assert.strictEqual(typeof readAsyncStart.event.fd, 'number'); + assert.strictEqual(readAsyncEnd.type, 'asyncEnd'); + assert.strictEqual(readAsyncEnd.event.api, 'callback'); + assert.strictEqual(typeof readAsyncEnd.event.fd, 'number'); + assert.strictEqual(readAsyncEnd.event.result, data.length); // bytes read + + // Promise operations publish the same family with api: 'promise'. + fsp.stat(target).then(common.mustCall((stats) => { + assert.strictEqual(typeof stats.size, 'number'); + + const statEvents = byOperation('stat'); + assert.ok(statEvents.length >= 4, 'expected stat start/end/asyncStart/asyncEnd'); + const statAsyncEnd = statEvents[statEvents.length - 1]; + assert.strictEqual(statAsyncEnd.type, 'asyncEnd'); + assert.strictEqual(statAsyncEnd.event.api, 'promise'); + assert.strictEqual(statAsyncEnd.event.path, target); + assert.ok('result' in statAsyncEnd.event); + + // Destination operations carry the `dest` field. + fs.rename(target, source, common.mustSucceed(() => { + const renameEvents = byOperation('rename'); + assert.ok(renameEvents.length >= 4, 'expected rename start/end/asyncStart/asyncEnd'); + const renameAsyncEnd = renameEvents[renameEvents.length - 1]; + assert.strictEqual(renameAsyncEnd.type, 'asyncEnd'); + assert.strictEqual(renameAsyncEnd.event.path, target); + assert.strictEqual(renameAsyncEnd.event.dest, source); + + // Failed operations publish an `error` event carrying the error object. + fs.readFile('/nonexistent-node-diagnostics-channel-fs', common.mustCall((err2) => { + assert.ok(err2); + const errorEvents = events.filter((e) => e.type === 'error'); + const error = errorEvents[errorEvents.length - 1]; + assert.ok(error, 'expected an error event'); + assert.strictEqual(error.event.api, 'callback'); + assert.strictEqual(error.event.operation, 'open'); + assert.strictEqual(error.event.path, '/nonexistent-node-diagnostics-channel-fs'); + assert.strictEqual(error.event.error.code, 'ENOENT'); + + fs.rm(source, { force: true }, common.mustCall()); + })); + })); + })); +}));