Why iosnoop (IO snooping files on disk) returns paths with question marks?

Question

If I'm running

sudo iosnoop | grep "gem"

and then in another terminal run

gem env

in the iosnoop terminal I see:

dtrace: error on enabled probe ID 4 (ID 1106: io:mach_kernel:buf_strategy:start): illegal operation in action #3 at DIF offset 0
dtrace: error on enabled probe ID 4 (ID 1106: io:mach_kernel:buf_strategy:start): illegal operation in action #3 at DIF offset 0
dtrace: error on enabled probe ID 4 (ID 1106: io:mach_kernel:buf_strategy:start): illegal operation in action #3 at DIF offset 0
dtrace: error on enabled probe ID 4 (ID 1106: io:mach_kernel:buf_strategy:start): illegal operation in action #3 at DIF offset 0
dtrace: error on enabled probe ID 4 (ID 1106: io:mach_kernel:buf_strategy:start): illegal operation in action #3 at DIF offset 0
...
dtrace: error on enabled probe ID 4 (ID 1106: io:mach_kernel:buf_strategy:start): illegal operation in action #3 at DIF offset 0
  501 54406 R 21523616    512       bash ??/bin/gem
  501 94092 R 141320288   4096       bash ??/bin/gem
  501 94092 R 141320168   4096       ruby ??/1.8/rubygems.rb
  501 94092 R 141320208   4096       ruby ??/1.8/rubygems.rb
  501 94092 R 141319208   4096       ruby ??/rubygems/errors.rb
  501 94092 R 141319856   4096       ruby ??/rubygems/specification.rb
  501 94092 R 141319864   4096       ruby ??/rubygems/specification.rb
  501 94092 R 141319872   4096       ruby ??/rubygems/specification.rb
  501 94092 R 141319888   4096       ruby ??/rubygems/specification.rb
  501 94092 R 141319896   4096       ruby ??/rubygems/specification.rb
  501 94092 R 141319904   4096       ruby ??/rubygems/specification.rb
  501 94092 R 141319928   4096       ruby ??/rubygems/specification.rb
  501 94092 R 141319936   4096       ruby ??/rubygems/specification.rb
  501 94092 R 141319944   4096       ruby ??/rubygems/specification.rb
  501 94092 R 141320176   4096       ruby ??/1.8/rubygems.rb
  501 94092 R 141320184   4096       ruby ??/1.8/rubygems.rb
  ...

What are the question marks near ruby in the path to the files are treated:

ruby ??/1.8/rubygems.rb

? And how can I find the absolute path to all these files?

Additional question - why are the errors here:

dtrace: error on enabled probe ID 4 (ID 1106: io:mach_kernel:buf_strategy:start): illegal operation in action #3 at DIF offset 0

?

Answer 1

The short answers are:

1. The ?? signify that the remaining pathname is unknown,
2. you can't extract the absolute path and
3. this is a feature, not a bug, of DTrace on OS X.

An explanation of these points requires some familiarity with DTrace; if appropriate then start with the introduction to the Solaris version.

iosnoop is a script that exploits the DTrace observability framework. In particular, it uses the io provider's start and done probes; the start probe exposes a request's bufinfo_t, the target device's devinfo_t and the corresponding file's fileinfo_t. The fileinfo_t is not a native Darwin type: it is a structure provided by dtrace(1) that provides a convenient abstraction of a file for the benefit of users. For example, amongst its members is fi_pathname, which should give the full pathname of a file.

Having an abstracted description shields users, and their scripts, from knowledge of and changes to the underlying implementation of the operating system. In theory, it also allows for a single script to run on different operating systems altogether.

A fileinfo_t is constructed and populated dynamically using a DTrace translator described in /usr/lib/dtrace/io.d. This shows the transformation from the OS-specific types to the abstraction. In the case of Snow Leopard I see that fi_pathname is constructed from the string "??/" followed by some derivates of the IO buffer. I'm no Darwin expert but I infer that it simply doesn't record full pathnames in its vnodes. This, hence, is the origin of the "??" in the output of your script and also the reason why I assume that the absolute pathnames are unavailable.

Finally, your DTrace errors. For whatever reasons, Apple's port of DTrace is subtly crippled in that it precludes tracing of various processes, and the error message that you see is a characteristic symptom. Specifically, the complaint is about the line

start_uid[this->dev, this->blk] = (int)uid;

and it turns out that (again, on Snow Leopard), trying to evaluate uid on any of the launchd, diskimages-help and kernel_task processes results in exactly this error. I presume that these processes are "out of bounds" and the errors that you see are the consequences of Apple's modifications.

Answer 2

While the answer above gives a good technical background, if you just want to get the full pathname of opened files I'm able to do this using raw DTrace on OS X via:

sudo dtrace -n 'syscall::open*:entry { printf("%s %s",execname,copyinstr(arg0)); }'

This will show file opens, but not reads or writes. I got this from Brendan Gregg's handy DTrace one liners page: http://www.brendangregg.com/DTrace/dtrace_oneliners.txt

Sadly, I still don't understand why iosnoop isn't giving the full path, when it appears that it is theoretically possible.

Answer 3

So the answer is actually fairly simple. A vnode has following structure

struct vnode{
    // other attrs
    const char *v_name;                     /* name component of the vnode */
    vnode_t v_parent; 
}

Normally to get a path from a vnode you call vn_getpath, which ends up calling build_path_with_parent. The implementation of this is actually slightly more non-trivial than you'd think, apple even says

Paths to vnodes are not always straightforward: a file with multiple hard-links will have multiple pathnames, and it is sometimes impossible to determine a vnode's full path. vn_getpath() will not enter the filesystem.

and there's some locking going on, etc. As Robert Harris mentioned, Apple populates fi_pathname as

fi_pathname = (F == NULL) ? "<none>" :
        F->fg_ops->fo_type != DTYPE_VNODE ? "<unknown (not a vnode)>" :
            strjoin("??/",
            strjoin(((struct vnode *)F->fg_data)->v_parent == NULL ? "<unknown (NULL v_parent)>" :
                (((struct vnode *)F->fg_data)->v_parent->v_name == NULL ? "<unknown (NULL v_name)>" :
                 ((struct vnode *)F->fg_data)->v_parent->v_name),
                strjoin("/",
                    ((struct vnode *)F->fg_data)->v_name == NULL ? "<unknown (NULL v_name)>" :
                    ((struct vnode *)F->fg_data)->v_name)));

basically, they try to walk the tree manually, but they only go 2 levels up, which is why you have a ?? at the beginning. Now I don't know why they didn't just call the full vn_getpath when populating this, maybe as evidenced by a comment in Apple's source they thought this would be too much of a performance hit

/* XXX Really want vn_getpath(curproc->p_fd.fd_rdir, , ) but that takes namecache_rw_lock XXX */

or maybe it's a technical limitation (e.g. dtrace scripts can't call kernel functions). But whatever the reason, the fi_pathname epxposed is only 2 levels deep.

But of course there's no reason why we can't just traverse deeper ourselves. I don't know just doing the naive traversal gives the wrong answer in any case, but it seems to work fine in my testing.

For instance see this example macvfssnoop modified from the dtrace book:

#!/usr/sbin/dtrace -s

#pragma D option quiet
#pragma D option defaultargs
#pragma D option switchrate=10hz

dtrace:::BEGIN
{
    printf("%-12s %6s %6s %-12.12s %-12s %-4s %s\n", "TIME(ms)", "UID",
        "PID", "PROCESS", "CALL", "KB", "PATH");
}

/* see sys/bsd/sys/vnode_if.h */

fbt::VNOP_WRITE:entry
{
    this->vnode = ((struct vnode *)arg0);
    this->parent = this->vnode == NULL ? NULL : this->vnode->v_parent;
    this->gp = this->parent == NULL ? NULL : this->parent->v_parent;
    this->ggp = this->gp == NULL ? NULL : this->gp->v_parent;
    this->gggp = this->ggp == NULL ? NULL : this->ggp->v_parent;

    this->selfpath = (this->vnode == NULL || this->vnode->v_name == NULL) ? "" : strjoin("/", this->vnode->v_name);
    this->parentpath = (this->parent == NULL || this->parent->v_name == NULL) ? "" : strjoin("/", this->parent->v_name);
    this->gpath = (this->gp == NULL || this->gp->v_name == NULL) ? "" : strjoin("/", this->gp->v_name);
    this->ggpath = (this->ggp == NULL || this->ggp->v_name == NULL) ? "" : strjoin("/", this->ggp->v_name);
    this->gggpath = (this->gggp == NULL || this->gggp->v_name == NULL) ? "" : strjoin("/", this->gggp->v_name);

    this->path1 = this->selfpath;
    this->path2 = strjoin(this->parentpath, this->path1);
    this->path3 = strjoin(this->gpath, this->path2);
    this->path4 = strjoin(this->ggpath, this->path3);
    this->path5 = strjoin(this->gggpath, this->path4);

    self->path = this->path5;
    self->kb = ((struct uio *)arg1)->uio_resid_64 / 1024;
}

fbt::VNOP_WRITE:entry
/execname != "dtrace" && ($$1 == NULL || $$1 == execname)/
{
    printf("%-12d %6d %6d %-12.12s %-12s %-4d %s\n", timestamp / 1000000,
    uid, pid, execname, probefunc, self->kb,
    self->path != NULL ? stringof(self->path) : "<null>");
}

fbt::VNOP_WRITE:entry
{
    self->path = 0; self->kb = 0;
}

Another option as Anton noted is to trace at the syscall level instead of the VFS level, in which case your path is directly an argument to the syscall. However even in this case, the path can still be a relative path (relative to the program's working directory) so you'd also need to print out the working directory, like how pathopens.d does.

Also see https://lists.apple.com/archives/filesystem-dev/2012/Jan/msg00006.html