"Error: failed to load DOF: No such file or directory" on enable() on FreeBSD/amd64 10.3 on node 8.10.0

[tcort]

Symptoms

I'm using node v8.10.0 built from source on FreeBSD/amd64 10.3 (built with clang and clang++, no configure flags given). I tried dtrace-provider (just the simple code snippet from the README) and it results in an error: Error: failed to load DOF: No such file or directory.

Version Numbers:

node v8.10.0
npm 5.7.1
FreeBSD/amd64 10.3
dtrace "Sun D 1.12.1"
dtrace-provider (HEAD 1474252dccf5c85b7f933e8878859e6cb27690ac)

Steps to reproduce:

Clone the repo...

$ git clone https://github.com/chrisa/node-dtrace-provider && cd node-dtrace-provider
$ git log | head -n 1
commit 1474252dccf5c85b7f933e8878859e6cb27690ac

Install and Build

$ npm i

> dtrace-provider@0.8.6 install /usr/home/thomasc/repos/node-dtrace-provider
> node-gyp rebuild || node suppress-error.js

gmake: Entering directory '/usr/home/thomasc/repos/node-dtrace-provider/build'
  ACTION binding_gyp_ndtp_target_build_ndtp .
  TOUCH Release/obj.target/ndtp.stamp
gmake: Leaving directory '/usr/home/thomasc/repos/node-dtrace-provider/build'
added 28 packages from 18 contributors in 4.241s

Make a little demo based on the example in README.md

$ vi demo.js
$ cat demo.js
var d = require('./');
var dtp = d.createDTraceProvider("nodeapp");
var p1 = dtp.addProbe("probe1", "int", "int");
var p2 = dtp.addProbe("probe2", "char *");
dtp.enable();

Run it...

$ node demo.js
/usr/home/thomasc/repos/node-dtrace-provider/demo.js:5
dtp.enable();
    ^

Error: failed to load DOF: No such file or directory
    at Object.<anonymous> (/usr/home/thomasc/repos/node-dtrace-provider/demo.js:5:5)
    at Module._compile (module.js:652:30)
    at Object.Module._extensions..js (module.js:663:10)
    at Module.load (module.js:565:32)
    at tryModuleLoad (module.js:505:12)
    at Function.Module._load (module.js:497:3)
    at Function.Module.runMain (module.js:693:10)
    at startup (bootstrap_node.js:188:16)
    at bootstrap_node.js:609:3

Oddly, if I've run dtrace since the last boot, I don't get the error.

# dtrace -Z -n 'nodeapp*:::probe1{ trace(arg0); trace(arg1) }'
dtrace: description 'nodeapp*:::probe1' matched 0 probes
^C
$ node demo.js
$ echo $?
0

Build Log

$ V=1 npm i

> dtrace-provider@0.8.6 install /usr/home/thomasc/repos/node-dtrace-provider
> node-gyp rebuild || node suppress-error.js

gmake: Entering directory '/usr/home/thomasc/repos/node-dtrace-provider/build'
  LD_LIBRARY_PATH=/usr/home/thomasc/repos/node-dtrace-provider/build/Release/lib.host:/usr/home/thomasc/repos/node-dtrace-provider/build/Release/lib.target:$LD_LIBRARY_PATH; export LD_LIBRARY_PATH; cd ../.; bash build.sh
+ buildUSDT
+ [[ -z '' ]]
+ [[ -z 1 ]]
+ unset MAKEFLAGS
++ node -e 'console.log(process.arch === '\''x64'\'' ? '\''x86_64'\'' : '\''i386'\'')'
+ export ARCH=x86_64
+ ARCH=x86_64
+ echo 'Building libusdt for x86_64'
Building libusdt for x86_64
+ [[ -z '' ]]
++ which gmake
+ MAKE=/usr/local/bin/gmake
+ [[ -z /usr/local/bin/gmake ]]
+ /usr/local/bin/gmake -C libusdt clean all
gmake[1]: Entering directory '/usr/home/thomasc/repos/node-dtrace-provider/libusdt'
rm -f *.gch
rm -f *.o
rm -f libusdt.a
rm -f test_usdt
rm -f test_usdt32
rm -f test_usdt64
rm -f test_mem_usage
gcc -O2 -Wall -Wno-error=unknown-pragmas -I/usr/src/sys/cddl/compat/opensolaris -I/usr/src/sys/cddl/contrib/opensolaris/uts/common -fPIC   -c -o usdt.o usdt.c
In file included from usdt_internal.h:14:0,
                 from usdt.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:35:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI"
 ^
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/processor.h:36:0,
                 from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:56,
                 from usdt_internal.h:14,
                 from usdt.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/procset.h:34:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI" /* SVr4.0 1.6 */
 ^
gcc -O2 -Wall -Wno-error=unknown-pragmas -I/usr/src/sys/cddl/compat/opensolaris -I/usr/src/sys/cddl/contrib/opensolaris/uts/common -fPIC   -c -o usdt_dof_file.o usdt_dof_file.c
In file included from usdt_internal.h:14:0,
                 from usdt_dof_file.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:35:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI"
 ^
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/processor.h:36:0,
                 from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:56,
                 from usdt_internal.h:14,
                 from usdt_dof_file.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/procset.h:34:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI" /* SVr4.0 1.6 */
 ^
gcc -O2 -Wall -Wno-error=unknown-pragmas -I/usr/src/sys/cddl/compat/opensolaris -I/usr/src/sys/cddl/contrib/opensolaris/uts/common -fPIC -o usdt_tracepoints.o -c usdt_tracepoints_x86_64.s
gcc -O2 -Wall -Wno-error=unknown-pragmas -I/usr/src/sys/cddl/compat/opensolaris -I/usr/src/sys/cddl/contrib/opensolaris/uts/common -fPIC   -c -o usdt_probe.o usdt_probe.c
In file included from usdt_internal.h:14:0,
                 from usdt_probe.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:35:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI"
 ^
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/processor.h:36:0,
                 from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:56,
                 from usdt_internal.h:14,
                 from usdt_probe.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/procset.h:34:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI" /* SVr4.0 1.6 */
 ^
gcc -O2 -Wall -Wno-error=unknown-pragmas -I/usr/src/sys/cddl/compat/opensolaris -I/usr/src/sys/cddl/contrib/opensolaris/uts/common -fPIC   -c -o usdt_dof.o usdt_dof.c
In file included from usdt_internal.h:14:0,
                 from usdt_dof.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:35:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI"
 ^
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/processor.h:36:0,
                 from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:56,
                 from usdt_internal.h:14,
                 from usdt_dof.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/procset.h:34:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI" /* SVr4.0 1.6 */
 ^
gcc -O2 -Wall -Wno-error=unknown-pragmas -I/usr/src/sys/cddl/compat/opensolaris -I/usr/src/sys/cddl/contrib/opensolaris/uts/common -fPIC   -c -o usdt_dof_sections.o usdt_dof_sections.c
In file included from usdt_internal.h:14:0,
                 from usdt_dof_sections.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:35:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI"
 ^
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/processor.h:36:0,
                 from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:56,
                 from usdt_internal.h:14,
                 from usdt_dof_sections.c:5:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/procset.h:34:0: warning: ignoring #pragma ident  [-Wunknown-pragmas]
 #pragma ident "%Z%%M% %I% %E% SMI" /* SVr4.0 1.6 */
 ^
rm -f libusdt.a
ar cru libusdt.a usdt.o usdt_dof_file.o usdt_tracepoints.o usdt_probe.o usdt_dof.o usdt_dof_sections.o
ranlib libusdt.a
gmake[1]: Leaving directory '/usr/home/thomasc/repos/node-dtrace-provider/libusdt'
+ LIBUSDT_STATUS=0
+ [[ 0 -ne 0 ]]
+ buildNDTP
+ [[ -z '' ]]
+ [[ -z 1 ]]
+ node-gyp rebuild -C src
gmake[1]: Entering directory '/usr/home/thomasc/repos/node-dtrace-provider/src/build'
  c++ '-DNODE_GYP_MODULE_NAME=DTraceProviderBindings' '-DUSING_UV_SHARED=1' '-DUSING_V8_SHARED=1' '-DV8_DEPRECATION_WARNINGS=1' '-D_LARGEFILE_SOURCE' '-D_FILE_OFFSET_BITS=64' '-DBUILDING_NODE_EXTENSION' -I/home/thomasc/.node-gyp/8.10.0/include/node -I/home/thomasc/.node-gyp/8.10.0/src -I/home/thomasc/.node-gyp/8.10.0/deps/uv/include -I/home/thomasc/.node-gyp/8.10.0/deps/v8/include -I/usr/src/cddl/compat/opensolaris -I/usr/src/sys/cddl/compat/opensolaris -I/usr/src/sys/cddl/contrib/opensolaris/uts/common -I../../libusdt -I../../node_modules/nan  -fPIC -pthread -Wall -Wextra -Wno-unused-parameter -m64 -D_LIBCPP_TRIVIAL_PAIR_COPY_CTOR=1 -O3 -fno-omit-frame-pointer -fno-rtti -fno-exceptions -std=gnu++0x -MMD -MF ./Release/.deps/Release/obj.target/DTraceProviderBindings/dtrace_provider.o.d.raw   -c -o Release/obj.target/DTraceProviderBindings/dtrace_provider.o ../dtrace_provider.cc
In file included from ../dtrace_provider.cc:1:
In file included from ../dtrace_provider.h:8:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:35:9: warning: unknown pragma ignored [-Wunknown-pragmas]
#pragma ident   "%Z%%M% %I%     %E% SMI"
        ^
In file included from ../dtrace_provider.cc:1:
In file included from ../dtrace_provider.h:8:
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:56:
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/processor.h:36:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/procset.h:34:9: warning: unknown pragma ignored [-Wunknown-pragmas]
#pragma ident   "%Z%%M% %I%     %E% SMI"        /* SVr4.0 1.6 */
        ^
../dtrace_provider.cc:89:35: warning: 'NewInstance' is deprecated [-Wdeprecated-declarations]
    v8::Local<Object> pd = klass->NewInstance();
                                  ^
/home/thomasc/.node-gyp/8.10.0/include/node/v8.h:3851:52: note: 'NewInstance' declared here
  V8_DEPRECATED("Use maybe version", Local<Object> NewInstance() const);
                                                   ^
/home/thomasc/.node-gyp/8.10.0/include/node/v8config.h:321:3: note: expanded from macro 'V8_DEPRECATED'
  declarator __attribute__((deprecated))
  ^
../dtrace_provider.cc:96:10: warning: 'ForceSet' is deprecated [-Wdeprecated-declarations]
    Nan::ForceSet(pd, Nan::New<String>("__prov__").ToLocalChecked(), obj,
         ^
../../node_modules/nan/nan_maybe_43_inl.h:130:35: note: 'ForceSet' declared here
NAN_DEPRECATED inline Maybe<bool> ForceSet(
                                  ^
4 warnings generated.
  c++ '-DNODE_GYP_MODULE_NAME=DTraceProviderBindings' '-DUSING_UV_SHARED=1' '-DUSING_V8_SHARED=1' '-DV8_DEPRECATION_WARNINGS=1' '-D_LARGEFILE_SOURCE' '-D_FILE_OFFSET_BITS=64' '-DBUILDING_NODE_EXTENSION' -I/home/thomasc/.node-gyp/8.10.0/include/node -I/home/thomasc/.node-gyp/8.10.0/src -I/home/thomasc/.node-gyp/8.10.0/deps/uv/include -I/home/thomasc/.node-gyp/8.10.0/deps/v8/include -I/usr/src/cddl/compat/opensolaris -I/usr/src/sys/cddl/compat/opensolaris -I/usr/src/sys/cddl/contrib/opensolaris/uts/common -I../../libusdt -I../../node_modules/nan  -fPIC -pthread -Wall -Wextra -Wno-unused-parameter -m64 -D_LIBCPP_TRIVIAL_PAIR_COPY_CTOR=1 -O3 -fno-omit-frame-pointer -fno-rtti -fno-exceptions -std=gnu++0x -MMD -MF ./Release/.deps/Release/obj.target/DTraceProviderBindings/dtrace_probe.o.d.raw   -c -o Release/obj.target/DTraceProviderBindings/dtrace_probe.o ../dtrace_probe.cc
In file included from ../dtrace_probe.cc:1:
In file included from ../dtrace_provider.h:8:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:35:9: warning: unknown pragma ignored [-Wunknown-pragmas]
#pragma ident   "%Z%%M% %I%     %E% SMI"
        ^
In file included from ../dtrace_probe.cc:1:
In file included from ../dtrace_provider.h:8:
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:56:
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/processor.h:36:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/procset.h:34:9: warning: unknown pragma ignored [-Wunknown-pragmas]
#pragma ident   "%Z%%M% %I%     %E% SMI"        /* SVr4.0 1.6 */
        ^
2 warnings generated.
  c++ '-DNODE_GYP_MODULE_NAME=DTraceProviderBindings' '-DUSING_UV_SHARED=1' '-DUSING_V8_SHARED=1' '-DV8_DEPRECATION_WARNINGS=1' '-D_LARGEFILE_SOURCE' '-D_FILE_OFFSET_BITS=64' '-DBUILDING_NODE_EXTENSION' -I/home/thomasc/.node-gyp/8.10.0/include/node -I/home/thomasc/.node-gyp/8.10.0/src -I/home/thomasc/.node-gyp/8.10.0/deps/uv/include -I/home/thomasc/.node-gyp/8.10.0/deps/v8/include -I/usr/src/cddl/compat/opensolaris -I/usr/src/sys/cddl/compat/opensolaris -I/usr/src/sys/cddl/contrib/opensolaris/uts/common -I../../libusdt -I../../node_modules/nan  -fPIC -pthread -Wall -Wextra -Wno-unused-parameter -m64 -D_LIBCPP_TRIVIAL_PAIR_COPY_CTOR=1 -O3 -fno-omit-frame-pointer -fno-rtti -fno-exceptions -std=gnu++0x -MMD -MF ./Release/.deps/Release/obj.target/DTraceProviderBindings/dtrace_argument.o.d.raw   -c -o Release/obj.target/DTraceProviderBindings/dtrace_argument.o ../dtrace_argument.cc
In file included from ../dtrace_argument.cc:1:
In file included from ../dtrace_provider.h:8:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:35:9: warning: unknown pragma ignored [-Wunknown-pragmas]
#pragma ident   "%Z%%M% %I%     %E% SMI"
        ^
In file included from ../dtrace_argument.cc:1:
In file included from ../dtrace_provider.h:8:
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/dtrace.h:56:
In file included from /usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/processor.h:36:
/usr/src/sys/cddl/contrib/opensolaris/uts/common/sys/procset.h:34:9: warning: unknown pragma ignored [-Wunknown-pragmas]
#pragma ident   "%Z%%M% %I%     %E% SMI"        /* SVr4.0 1.6 */
        ^
2 warnings generated.
  c++ -shared -pthread -rdynamic -m64 -Wl,--export-dynamic  -Wl,-soname=DTraceProviderBindings.node -o Release/obj.target/DTraceProviderBindings.node -Wl,--start-group Release/obj.target/DTraceProviderBindings/dtrace_provider.o Release/obj.target/DTraceProviderBindings/dtrace_probe.o Release/obj.target/DTraceProviderBindings/dtrace_argument.o -Wl,--end-group -L/usr/home/thomasc/repos/node-dtrace-provider/src/../libusdt -l usdt
  rm -rf "Release/DTraceProviderBindings.node" && cp -af "Release/obj.target/DTraceProviderBindings.node" "Release/DTraceProviderBindings.node"
gmake[1]: Leaving directory '/usr/home/thomasc/repos/node-dtrace-provider/src/build'
+ NODE_GYP_STATUS=0
+ [[ 0 -ne 0 ]]
+ exit 0
  touch Release/obj.target/ndtp.stamp
gmake: Leaving directory '/usr/home/thomasc/repos/node-dtrace-provider/build'
added 28 packages from 18 contributors in 4.531s

[No9]

Hey @tcort Apologies I missed this - FreeBSD 10.3 Doesn't have dtrace enabled by default - It is in 11.0 or above versions
The clue is in

Oddly, if I've run dtrace since the last boot, I don't get the error.

You can load dtrace by running kldload dtraceall
If you want that to persist beyond reboots you need edit /boot/loader.conf or /boot/loader.local.conf add the line dtraceall_load="YES"

[lapo-luchini]

@No9 it also happens on an up-to-date FreeBSD:

% uname -a
FreeBSD lapo.andxor.it 11.1-RELEASE-p10 FreeBSD 11.1-RELEASE-p10 #0: Tue May  8 05:21:56 UTC 2018     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64
% cat testDTrace.js 
var dtrace = require('dtrace-provider');
PROVIDER = dtrace.createDTraceProvider('restify');
PROVIDER.addProbe('route-start', 'char *', 'char *', 'int', 'char *', 'char *', 'json');
PROVIDER.enable();
% node testDTrace
/home/lapo/svn/nodejs/axosms/trunk/testDTrace.js:4
PROVIDER.enable();
         ^

Error: failed to load DOF: No such file or directory
    at Object.<anonymous> (/home/lapo/test/testDTrace.js:4:10)
    at Module._compile (internal/modules/cjs/loader.js:702:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:713:10)
    at Module.load (internal/modules/cjs/loader.js:612:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:551:12)
    at Function.Module._load (internal/modules/cjs/loader.js:543:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:744:10)
    at startup (internal/bootstrap/node.js:238:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:572:3)

(I was trying to debug the error in have in restify so I extracted a minimal test case from its usage)

[lapo-luchini]

restify use-case does wrap the constructor in try/catch to ignore DTrace on system that don't use it, but unfortunately the enable() is outside of the try.
When DTrace is not available, do you think the constructor should trow (and thus restify usage is already ok) or is it expected that only enable() can fail? (in this case I will suggest or PR them to wrap everything inside the try)

[lapo-luchini]

I noticed that other modules, e.g. bunyan, use this with no try/catch; it might be worth supporting "FreeBSD with no dtrace module loaded in the kernel" as an unsupported platform and automatically using «a stub no-op implementation provided for compatibility» (as stated in the README).

[No9]

Hi @lapo-luchini

automatically using «a stub no-op implementation provided for compatibility»

I'm not 100% that covers all the scenarios
i.e. if you have a system that has successfully built the provider you would expect a failure if dtrace wasn't enabled not silently swallow it

Maybe the answer is to warn during the build or when the the module is loaded?

[lapo-luchini]

True that. Some more whild ideas:

1. "fail fast" (if possible?) fail on require: this would fix both restify and bunyan (with no change at all on their part) but could well break others that expected maybe a failure on new instead of require
2. "static flag": something like require('dtrace-provider').optional=true to be used before recursive requires (this would allow the most external user change but little control in inner modules)
3. continue failing on enable, stating it clearly in docs and opening PRs on all dependencies to check for that