Bug 222752 - DTrace: probe syscall::write:entry is not fired unless printf in action
Summary: DTrace: probe syscall::write:entry is not fired unless printf in action
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: CURRENT
Hardware: Any Any
: --- Affects Some People
Assignee: Mark Johnston
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-10-03 10:51 UTC by Hannes Mehnert
Modified: 2017-10-13 15:47 UTC (History)
1 user (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Hannes Mehnert 2017-10-03 10:51:19 UTC
I'm using rev322062, compiled (cc -o t t.c) the t.c below, which is a quite small test case just for this bug.

The lifecycle of t and DTrace are not equal - thus I try to communicate from the user application (t) to DTrace when to start instrumenting and when to stop.  I do this by t writing START and STOP onto stdout, and the D script to set a thread-local variable.

The probe sysctl::write:entry in t.d is not executed - the same one in t2.d, where a printf is added - is executed.  My expectation from DTace is that t.d's sysctl::write:entry would also be executed.

I execute "doas ./d.t" in one shell, then execute ./t in another shell.  (Running dtrace -c obviously works because DTrace then exits once t exits, but this is not a solution for my use case (a much bigger instrumentation where I only want to trace after some initialisation).

t.c
==============================
#include <stdio.h>
#include <unistd.h>

int main (int argc, char ** argv) {
  printf("START");
  printf("BOOOOOOOO\n");
  printf("STOP");
  printf("done now\n");
}
==============================

t.d
==============================
#!/usr/sbin/dtrace -Cs

#pragma D option quiet

#define prog "t"
#define act execname == prog && self->started == 1

syscall::write:entry
/arg0 == 1 && (string)copyin(arg1, 5) == "START"/
{
  self->started = 1;
}

syscall::write:entry
/act && arg0 == 1 && (string)copyin(arg1, 4) == "STOP" && self->started == 1/
{
  exit(0);
}
==============================

t2.d
==============================
#!/usr/sbin/dtrace -Cs

#pragma D option quiet

#define prog "t"
#define act execname == prog && self->started == 1

syscall::write:entry
/arg0 == 1 && (string)copyin(arg1, 5) == "START"/
{
  printf("starting\n");
  self->started = 1;
}

syscall::write:entry
/act && arg0 == 1 && (string)copyin(arg1, 4) == "STOP" && self->started == 1/
{
  printf("exiting now\n");
  exit(0);
}
==============================
Comment 1 Mark Johnston freebsd_committer freebsd_triage 2017-10-04 16:02:25 UTC
I can reproduce this on r324059.
Comment 2 Mark Johnston freebsd_committer freebsd_triage 2017-10-10 22:59:06 UTC
The issue seems to be that (string)copyin(arg1, 4) doesn't work as one might expect: it doesn't nul-terminate the buffer we copied in. I think this is a bug, since the subsequent strcmp with "STOP" results in an access to "uninitialized" scratch space, but I'm still investigating.
Comment 3 Mark Johnston freebsd_committer freebsd_triage 2017-10-13 14:10:11 UTC
Still looking at this. Indeed, the generated DIF is the same with or without the casts to the return value of copyin(), but it's not clear to me how to address
that.

I'll note that there's a simple "workaround": just use copyinstr() with the optional second parameter to bound the length.
Comment 4 Hannes Mehnert 2017-10-13 15:19:06 UTC
(In reply to Mark Johnston from comment #3)
Thanks for looking into this.  I don't understand "use copyinstr() with the optional second parameter to bound the length" quite.

In both t.d and t2.d above I use the same "copyin(arg1, 4)" -- i.e. using two parameters to that function.  What is the workaround you're suggesting?

The one which works for me is to include a "printf" in the probe body.
Comment 5 Mark Johnston freebsd_committer freebsd_triage 2017-10-13 15:35:32 UTC
You can replace (string)copyin(arg1, 4) with just copyinstr(arg1, 4).
copyinstr()'s second parameter is optional; copyinstr(arg1) will copy in the
whole string. If I make this substitution in your t.d script, the script
behaves as expected.

I still think this is a dtrace bug, but it's tricky to fix. The issue is that
casting the return value of copyin() doesn't cause the buffer to be nul-terminated, so the result of the comparison with "STOP" depends on what
follows the copyin() value in the tracing buffer. The printf() just has some
side effect which allows the comparison to succeed, so it's really an accidental workaround.
Comment 6 Mark Johnston freebsd_committer freebsd_triage 2017-10-13 15:39:19 UTC
One possible fix would be to have the parser transform (string)copyin(foo, bar)
into copyinstr(foo, bar); I'm just not sure if there are other situations where a cast to string works as expected.
Comment 7 Hannes Mehnert 2017-10-13 15:47:52 UTC
(In reply to Mark Johnston from comment #5)
thank you again for your detailed explanation!