popt vs. samba vs. pcp: nonintrustive debugging with systemtap

It took a day to get to the bottom of a peculiar software problem that hampered integrating Samba and PCP. It took dipping into three separate source code-bases and one ridiculously manly tool.

The task at hand was checking whether the samba statistics-gathering agent for PCP was working fine with the new Fedora rawhide version of Samba 4.1rc2. This is the first version in a long time built with self-profiling capabilities. These work something like the PCP MMV library - counters plopped into a shared memory segment, printed to the user on demand with smbstatus --profile.

The way some of the simpler PCP agents work is by running an application-specific program, parsing its output, and disseminating into the PCP. This makes them easy to test, since one can hand-run those same programs (like smbstatus above), and beat the parsing logic into shape. There were some changes since the last major samba version this worked, so a certain number of bruises were necessarily inflicted on the PCP agent code. However, in the end, it ran fine.

Well, almost. It ran fine, when it was run by hand. It did not run, when run from the PCP infrastructure on-demand. From a bit of diagnostic extension, it was possible to see that when pmdasamba.pl ran smbstatus --profile, it received output as per smbstatus only, no --profile. Similarly, other --options were also ignored, with no indication why.

The possibilities ranged from annoying to the sublime. Some sort of broken chroot or $PATH invoking the wrong smbstatus binary? Is there another one hiding on the system somewhere? Some kind of string/memory corruption? Some kind of kernel privilege issue? Something about having a tty available as opposed to a plain pipe? These and others had to be gradually eliminated.

The most direct route might have been arranging to run smbstatus under a debugger, once eventually invoked by the PCP code. Assuming it got that far, one could step through it to see why it's not printing the profile data (whereas the hand-invoked one was). But normal debuggers cannot monitor the system for an as-yet-nonexistent process, carefully see what it's doing, but without interfering with the other processes interacting with it. It's almost as though one needs a non-intrusive systemwide programmable debugger.

Luckily, on Linux we happen to have one. A single systemtap script, attached to a process by name (even before one's started), to get a statement-by-statement trace. OK, that's a lot of data, but finally it's getting real data rather than speculating about possible causes.

# yum -y install samba-debuginfo
% stap -e 'probe process("smbstatus").statement("*@*:*") {println (pid(), " ", pp())}' &
% smbstatus --profile

The working case went something like:

28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:367")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:368")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:370")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:372")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:344")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:342")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:381")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:407")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:381")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:426")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:429")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:433")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:441")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:455")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:462")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:465")
28265 process("/usr/bin/smbstatus").statement("status_profile_dump@../source3/utils/status_profile.c:51")
28265 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:560")

The failing case instead went like:

28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:367")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:368")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:370")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:372")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:344")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:342")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:381")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:426")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:429")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:433")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:441")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:455")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:462")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:473")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:474")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:475")
28271 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:476")

The working and non-working cases diverged control around lines 381 of source3/utils/status.c (from the samba4 source code), which implicated libpopt:

    378         pc = poptGetContext(NULL, argc, (const char **) argv, long_options, 
    379                             POPT_CONTEXT_KEEP_FIRST);
    380 
    381         while ((c = poptGetNextOpt(pc)) != -1) {
    382                 switch (c) {

So it was time to put libpopt under the systemtap microscope, this time following along how internal function variables were changing value. $$vars$ pretty-prints local variables plus one level of structure content from pointers. (This script includes the execname check because otherwise other libpopt.so users in the system would litter the output.)

% stap -e '
probe process("smbstatus").statement("*@*:*"), process("/usr/lib64/libpopt.so").function("*").*
  {if (execname()=="smbstatus") println (pid(), " ", pp()," ",$$vars$)}'

The result was quite verbose, as one might expect, but full of priceless actual internal state. Here's the top of the non-working case:

14718 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:367") argc=2 argv="<9D>y<8A>^?" c=? profile_only=0 show_processes=? show_locks=? show_shares=? show_notify=0 pc={...} long_options=[{...}, .
..] frame=0x2b201f266120 ret=0 msg_ctx={.id={...}, .event_ctx=?, .callbacks=?, .local=?, .remote=?}
14718 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:368") argc=2 argv="<9D>y<8A>^?" c=? profile_only=0 show_processes=? show_locks=? show_shares=? show_notify=0 pc={...} long_options=[{...}, .
..] frame=0x2b201f266120 ret=0 msg_ctx={.id={...}, .event_ctx=?, .callbacks=?, .local=?, .remote=?}
14718 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:370") argc=2 argv="<9D>y<8A>^?" c=? profile_only=0 show_processes=? show_locks=? show_shares=? show_notify=0 pc={...} long_options=[{...}, .
..] frame=0x2b201f266120 ret=0 msg_ctx={.id={...}, .event_ctx=?, .callbacks=?, .local=?, .remote=?}
14718 process("/usr/bin/smbstatus").statement("main@../source3/utils/status.c:372") argc=2 argv="<9D>y<8A>^?" c=? profile_only=0 show_processes=? show_locks=? show_shares=? show_notify=0 pc={...} long_options=[{...}, .
..] frame=0x2b201f266120 ret=0 msg_ctx={.id={...}, .event_ctx=?, .callbacks=?, .local=?, .remote=?}
14718 process("/usr/lib64/libpopt.so.0.0.0").function("poptGetContext@/usr/src/debug/popt-1.13/popt.c:162").call name="" argc=2 argv="<9D>y<8A>^?" options={.longName="", .shortName='\000', .argInfo=4, .arg=0x2b2021e6f320, .val=0, .descrip="Help options:", .argDescrip=""} flags=2 con={.optionStack=[...], .os=?, .leftovers=?, .numLeftovers=?, .nextLeftover=?, .options=?, .restLeftover=?, .appName=?, .aliases=?, .numAliases=?, .flags=?, .execs=?, .numExecs=?, .execFail=?, .finalArgv=?, .finalArgvCount=?, .finalArgvAlloced=?, .maincall=?, .doExec=?, .execPath=?, .execAbsolute=?, .otherHelp=?, .arg_s
14718 process("/usr/lib64/libpopt.so.0.0.0").function("poptGetContext@/usr/src/debug/popt-1.13/popt.c:162").exported name="" argc=2 argv="<9D>y<8A>^?" options={.longName="", .shortName='\000', .argInfo=4, .arg=0x2b2021e6f320, .val=0, .descrip="Help options:", .argDescrip=""} flags=2 con={.optionStack=[...], .os=?, .leftovers=?, .numLeftovers=?, .nextLeftover=?, .options=?, .restLeftover=?, .appName=?, .aliases=?, .numAliases=?, .flags=?, .execs=?, .numExecs=?, .execFail=?, .finalArgv=?, .finalArgvCount=?, .finalArgvAlloced=?, .maincall=?, .doExec=?, .execPath=?, .execAbsolute=?, .otherHelp=?, .arg_s
14718 process("/usr/lib64/libpopt.so.0.0.0").function("invokeCallbacksPRE@/usr/src/debug/popt-1.13/popt.c:64").call con={.optionStack=[...], .os=0x2b201f267380, .leftovers=0x2b201f266470, .numLeftovers=0, .nextLeftover=0, .options=0x7fffa68a6110, .restLeftover=0, .appName="", .aliases=0x0, .numAliases=0, .flags=6, .execs=0x0, .numExecs=0, .execFail="", .finalArgv=0x2b201f266570, .finalArgvCount=0, .finalArgvAlloced=4, .maincall=0x0, .doExec=0x0, .execPath="", .execAbsolute=1, .otherHelp="", .arg_strip=0x0} opt={.longName="", .shortName='\000', .argInfo=4, .arg=0x2b2021e6f320,
14718 process("/usr/lib64/libpopt.so.0.0.0").function("invokeCallbacksPRE@/usr/src/debug/popt-1.13/popt.c:64").call con={.optionStack=[...], .os=0x2b201f267380, .leftovers=0x2b201f266470, .numLeftovers=0, .nextLeftover=0, .options=0x7fffa68a6110, .restLeftover=0, .appName="", .aliases=0x0, .numAliases=0, .flags=6, .execs=0x0, .numExecs=0, .execFail="", .finalArgv=0x2b201f266570, .finalArgvCount=0, .finalArgvAlloced=4, .maincall=0x0, .doExec=0x0, .execPath="", .execAbsolute=1, .otherHelp="", .arg_strip=0x0} opt={.longName="", .shortName='\000', .argInfo=6, .arg=0x2b2021c6d19d,
...
and on and on
...

Divergence between this and a similarly messy working state was not immediately obvious with a barenaked eye

... and what eye isn't barenaked? Eyes with contact lenses aren't literally naked. Or maybe, they're just as (un)dressed than a sunbather wearing only sunscreen. There must be some information about this on the internet. We must investigate immediately. Please wait.

Click click click. Oh, wow. Click.

OK, we're back, thank you for waiting. Back to comparing two complicated textual logs. If only we could diff word-by-word, to see just those state changes that are different between the two. Yes, we can!.

% wdiff -3 log1 log2
======================================================================
[-14718-]{+14733+}
======================================================================
 [-argv="<9D>y<8A>^?"-] {+argv="Y<86>t^?"+}
======================================================================
 [-frame=0x2b201f266120-] {+frame=0x2ba8a3a79120+}
======================================================================

[-14718-]
{+14733+}
======================================================================
 [-argv="<9D>y<8A>^?"-] {+argv="Y<86>t^?"+}
======================================================================
 [-frame=0x2b201f266120-] {+frame=0x2ba8a3a79120+}
======================================================================

[-14718-]
{+14733+}
======================================================================
 [-argv="<9D>y<8A>^?"-] {+argv="Y<86>t^?"+}
======================================================================
 [-frame=0x2b201f266120-] {+frame=0x2ba8a3a79120+}
======================================================================

[-14718-]
{+14733+}
======================================================================
 [-argv="<9D>y<8A>^?"-] {+argv="Y<86>t^?"+}
======================================================================
 [-frame=0x2b201f266120-] {+frame=0x2ba8a3a79120+}
======================================================================

[-14718-]
{+14733+}
======================================================================
 [-argv="<9D>y<8A>^?"-] {+argv="Y<86>t^?"+}
======================================================================
 [-.arg=0x2b2021e6f320,-] {+.arg=0x2ba8a6682320,+}
======================================================================

[-14718-]
{+14733+}
======================================================================
 [-argv="<9D>y<8A>^?"-] {+argv="Y<86>t^?"+}
======================================================================
 [-.arg=0x2b2021e6f320,-] {+.arg=0x2ba8a6682320,+}
======================================================================

[-14718-]
{+14733+}
======================================================================
 [-.os=0x2b201f267380, .leftovers=0x2b201f266470,-] {+.os=0x2ba8a3a7b350, .leftovers=0x2ba8a3a7a440,+}
======================================================================
 [-.options=0x7fffa68a6110,-] {+.options=0x7ffffd746b50,+}
======================================================================
 [-.flags=6,-] {+.flags=2,+}
======================================================================
 [-.finalArgv=0x2b201f266570,-] {+.finalArgv=0x2ba8a3a7a540,+}
======================================================================
...
and on and on
...

The 14-thousand numbers are process id numbers, expected to be different. Memory pointers (those 0x2* hexadecimal numbers) are naturally different between runs due to ASLR or friends. But did you see the one about .flags? Let's look at it again without the wdiff duplicate-elision.

% wdiff log1 log2 | grep 'flags=6' | head -1
{+14733+} process("/usr/lib64/libpopt.so.0.0.0")
    .function("invokeCallbacksPRE@/usr/src/debug/popt-1.13/popt.c:64").call
    con={... [-.flags=6,-] {+.flags=2,+} ...}

(I elided some bits there by hand, instead of using a new systemtap script to focus in only on the flags variable. I got excited. Don't sue me!) So now we've got a particular location in code where the to runs diverge: popt.c:64. That's an inlined function, the caller being poptGetContext, wherein the flags are well and truly set. Behold:

    194 
    195     if (getenv("POSIXLY_CORRECT") || getenv("POSIX_ME_HARDER"))
    196         con->flags |= POPT_CONTEXT_POSIXMEHARDER;
    197

Indeed, POPT_CONTEXT_POSIXMEHARDER is exactly the difference of 4 (between the 2 and 6 values observed). Mystery solved! No environment variable? smbstatus --profile workie. With environment variable? No workie. Where did the environment variable come from? Some ancient mystery code from within the bowels of PCP, which for the moment we work around.

Lessons learned? I spent too long trying to work through the many possible context differences between the hand-run and pcp-invoked instances of smbstatus, instead of simply measuring the differences directly. Once I started using the proper tool for the job, the result was almost immediate.