dtrace discuss - May 2006 - how does one trace a dlloaded() module?

Hi fellow DTracers,
One problem I''ve come across with DTrace that I can''t seem
to find a resolution to is this: how do we DTrace functions
in a plugin to a library which is dlloaded by an executable?

Allan and I are interested in watching calls into functions
residing in fp.so.

fp.so is a plugin for /usr/lib/libcfgadm.so:

/usr/sbin/cfgadm starts, then
	dlloads /usr/lib/libcfgadm.so which quickly realises that
	it needs to
		dlload /usr/lib/cfgadm/{amd64/|sparcv9/}fp.so


We can trace calls in libcfgadm.so using the -Z flag, but not
calls into fp.so.


One assumes that this problem has already been solved... but
how? What part of tfm did we gloss over?

All suggestions gratefully received.



Thanks in advance,
James C. McPherson
--
Solaris Datapath Engineering
Data Management Group
Sun Microsystems

On Wed, May 31, 2006 at 09:58:56AM +1000, James C. McPherson
wrote:
> 
> Hi fellow DTracers,
> One problem I''ve come across with DTrace that I can''t
seem
> to find a resolution to is this: how do we DTrace functions
> in a plugin to a library which is dlloaded by an executable?
> 
> Allan and I are interested in watching calls into functions
> residing in fp.so.
> 
> fp.so is a plugin for /usr/lib/libcfgadm.so:
> 
> /usr/sbin/cfgadm starts, then
> 	dlloads /usr/lib/libcfgadm.so which quickly realises that
> 	it needs to
> 		dlload /usr/lib/cfgadm/{amd64/|sparcv9/}fp.so
> 
> 
> We can trace calls in libcfgadm.so using the -Z flag, but not
> calls into fp.so.
> 
> 
> One assumes that this problem has already been solved... but
> how? What part of tfm did we gloss over?
> 
> All suggestions gratefully received.
At least on Nevada, this is not too hard:

% cat tmpc.c
#include <dlfcn.h>
#include <errno.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>

int
main(int argc, char *argv[])
{
        void *h = dlopen("libsocket.so.1", RTLD_NOW | RTLD_GLOBAL);

        uint32_t (*htonl)(uint32_t) = (uint32_t (*)(uint32_t))
            dlsym(h, "htonl");

        return (htonl(0));
}
% cc -o tmpc tmpc.c
% dtrace -c ./tmpc -Zn ''pid$target:libsocket.so.1::entry{}''
dtrace: description ''pid$target:libsocket.so.1::entry'' matched
0 probes
dtrace: pid 135257 has exited
CPU     ID                    FUNCTION:NAME
  0  45962                      htonl:entry 
% 

You may need to use the ''-Z'' flag, so that the fact that your
probes don''t
match anything when main() begins doesn''t cause an error.

I know this doesn''t work on S10 FCS, but I''m fairly sure
it''s either being
backported or is already available in Solaris 10.

Cheers,
- jonathan

-- 
Jonathan Adams, Solaris Kernel Development

Jonathan Adams wrote:
...
> You may need to use the ''-Z'' flag, so that the fact that
your probes don''t
> match anything when main() begins doesn''t cause an error.
Hi Jonathan,
I''m already using the "-Z" flag, and I still have this
problem. The other
thing about your example is that htonl() is in libsocket. My problem is
that we get to fp.so via callbacks from libcfgadm.so, so we''ve got
another
level of indirection there.


thanks anyway,
James C. McPherson
--
Solaris Datapath Engineering
Data Management Group
Sun Microsystems

James C. McPherson wrote:
> Jonathan Adams wrote:
> ...
>> You may need to use the ''-Z'' flag, so that the fact
that your probes
>> don''t
>> match anything when main() begins doesn''t cause an error.
> I''m already using the "-Z" flag, and I still have this
problem. The other
> thing about your example is that htonl() is in libsocket. My problem is
> that we get to fp.so via callbacks from libcfgadm.so, so we''ve got
another
> level of indirection there.

I''ve got a solution -- thankyou to Seth Goldberg via irc:


1. create a shim for dlclose()
2. create a D file for the plugin functions to probe,
3. LD_PRELOAD_32=/path/to/shim /path/to/script.d -Z -c "command"


shim.c

int dlclose(void *p)
{      return (0); }

compile with
/usr/sfw/bin/gcc -fPIC -shared -o /tmp/shim -c /tmp/shim.c

example script:

#!/usr/sbin/dtrace -s

pid$target:fp.so.1::entry {
	printf(" ");
	@[stack()] = count();
}

pid$target:fp.so.1::return {
	printf(" ");
}
/* end script */



I guess the question now becomes, why do I have to use a shim
for dlclose() in order to trace my plugin?


thanks,
James C. McPherson
--
Solaris Datapath Engineering
Data Management Group
Sun Microsystems

On Wed, May 31, 2006 at 10:25:36AM +1000, James C. McPherson
wrote:
> Jonathan Adams wrote:
> ...
> >You may need to use the ''-Z'' flag, so that the fact
that your probes don''t
> >match anything when main() begins doesn''t cause an error.
> 
> Hi Jonathan,
> I''m already using the "-Z" flag, and I still have this
problem. The other
> thing about your example is that htonl() is in libsocket. My problem is
> that we get to fp.so via callbacks from libcfgadm.so, so we''ve got
another
> level of indirection there.
I''ve used two scripts in the past, one that looks for telltale
syscalls,
stops the victim, and starts a second script that uses the pid provider
to trace the victim.

The plug-in library I was looking at was libpam.  The telltale behaviour
was the opening of /etc/pam.conf.  This works w/o -Z, though -Z is way
neater :)

Nico
--

On Wed, May 31, 2006 at 10:46:10AM +1000, James C. McPherson
wrote:
> James C. McPherson wrote:
> >Jonathan Adams wrote:
> >...
> >>You may need to use the ''-Z'' flag, so that the
fact that your probes
> >>don''t
> >>match anything when main() begins doesn''t cause an error.
> >I''m already using the "-Z" flag, and I still have
this problem. The other
> >thing about your example is that htonl() is in libsocket. My problem is
> >that we get to fp.so via callbacks from libcfgadm.so, so we''ve
got another
> >level of indirection there.
> 
> 1. create a shim for dlclose()
> 2. create a D file for the plugin functions to probe,
> 3. LD_PRELOAD_32=/path/to/shim /path/to/script.d -Z -c "command"
> 
...
>
> I guess the question now becomes, why do I have to use a shim
> for dlclose() in order to trace my plugin?
Hrm.  With that, I''ve crafted a testcase:

--- cut here ---
#include <dlfcn.h>
#include <errno.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>

int
main(int argc, char *argv[])
{
        void *h = dlopen("libsocket.so.1", RTLD_NOW | RTLD_GLOBAL);

        uint32_t (*htonl)(uint32_t) = (uint32_t (*)(uint32_t))
            dlsym(h, "htonl");

        (void) htonl(0);

        (void) dlclose(h);
        h = dlopen("libsocket.so.1", RTLD_NOW | RTLD_GLOBAL);
        htonl = (uint32_t (*)(uint32_t))dlsym(h, "htonl");
        (void) htonl(0);

        return (0);
}
--- cut here ---
% cc -o tmpc tmpc.c
% dtrace -c ./tmpc -Zn ''pid$target:libsocket.so.1::entry{}''
dtrace: description ''pid$target:libsocket.so.1::entry'' matched
0 probes
dtrace: pid 138063 has exited
CPU     ID                    FUNCTION:NAME
  0  46371                      htonl:entry 

%

Interestingly, it looks like truss(1) *also* misses the second call:

% truss -t \!all -u ld::dlsym -u libsocket::htonl ./tmpc 
/1 at 1:   -> ld:dlsym(0xff350640, 0x1077c, 0x1, 0xff2f1dc4)
/1 at 1:   <- ld:dlsym() = 0xff313938
/1 at 1:   -> libsocket:htonl(0x0, 0x1077c, 0xff3f12c0, 0xff2f1dc4)
/1 at 1:   <- libsocket:htonl() = 0
/1 at 1:   -> ld:dlsym(0xff0a03e8, 0x10794, 0x1, 0xff2f1dc4)
/1 at 1:   <- ld:dlsym() = 0xff303938

So dlclose() is somehow interfering with noticing a dlopen().  This
might be a bug in librtld_db or libproc.  Please file a bug.

Cheers,
- jonathan

-- 
Jonathan Adams, Solaris Kernel Development

On Wed, May 31, 2006 at 03:31:46PM -0700, Jonathan Adams
wrote:
> Hrm.  With that, I''ve crafted a testcase:
> 
> --- cut here ---
> #include <dlfcn.h>
> #include <errno.h>
> #include <stdio.h>
> #include <stdlib.h>
> #include <string.h>
> #include <unistd.h>
> 
> int
> main(int argc, char *argv[])
> {
>         void *h = dlopen("libsocket.so.1", RTLD_NOW |
RTLD_GLOBAL);
> 
>         uint32_t (*htonl)(uint32_t) = (uint32_t (*)(uint32_t))
>             dlsym(h, "htonl");
> 
>         (void) htonl(0);
> 
>         (void) dlclose(h);
>         h = dlopen("libsocket.so.1", RTLD_NOW | RTLD_GLOBAL);
>         htonl = (uint32_t (*)(uint32_t))dlsym(h, "htonl");
>         (void) htonl(0);
> 
>         return (0);
> }
> --- cut here ---
> % cc -o tmpc tmpc.c
> % dtrace -c ./tmpc -Zn
''pid$target:libsocket.so.1::entry{}''
> dtrace: description ''pid$target:libsocket.so.1::entry''
matched 0 probes
> dtrace: pid 138063 has exited
> CPU     ID                    FUNCTION:NAME
>   0  46371                      htonl:entry 
> 
> %
> 
> Interestingly, it looks like truss(1) *also* misses the second call:
> 
> % truss -t \!all -u ld::dlsym -u libsocket::htonl ./tmpc 
> /1 at 1:   -> ld:dlsym(0xff350640, 0x1077c, 0x1, 0xff2f1dc4)
> /1 at 1:   <- ld:dlsym() = 0xff313938
> /1 at 1:   -> libsocket:htonl(0x0, 0x1077c, 0xff3f12c0, 0xff2f1dc4)
> /1 at 1:   <- libsocket:htonl() = 0
> /1 at 1:   -> ld:dlsym(0xff0a03e8, 0x10794, 0x1, 0xff2f1dc4)
> /1 at 1:   <- ld:dlsym() = 0xff303938
Interestingly, I''m only seeing this failure on SPARC.  intel boxes
appear
to work fine.

Cheers,
- jonathan

-- 
Jonathan Adams, Solaris Kernel Development

Jonathan Adams wrote:
...
> Interestingly, I''m only seeing this failure on SPARC.  intel boxes
appear
> to work fine.
I''ve got this on sparc and amd64. I''ll include that info in
the bug report
when I file it later today.


thanks for your help on this.

James C. McPherson
--
Solaris Datapath Engineering
Data Management Group
Sun Microsystems

Jonathan Adams wrote:
...
> So dlclose() is somehow interfering with noticing a dlopen().  This
> might be a bug in librtld_db or libproc.  Please file a bug.
Done:

6432571P3 library/libproc dlclose() does the hokey pokey and turns dlopen() 
all around


(The synopsis is Seth''s suggestion)


thanks,
James C. McPherson
--
Solaris Datapath Engineering
Data Management Group
Sun Microsystems

> Jonathan Adams wrote:
> ...
>> So dlclose() is somehow interfering with noticing a dlopen().  This
>> might be a bug in librtld_db or libproc.  Please file a bug.
>
> Done:
>
> 6432571P3 library/libproc dlclose() does the hokey pokey and turns dlopen()
> all around
>
>
> (The synopsis is Seth''s suggestion)
    Oh, sure, blame your psychosis on ME... ;)

  --S