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.
I've recently become a Hugh Howey fan. I don't remember who recommended his Wool shorts (books, not clothes!) on Amazon Kindle, but I owe that person a beverage; in turn I've taken Hugh's peer-reviews of books to heart and purchased some of his recommendations. (But I'm not a mindless slave! Stop making me buy things!) Earlier this evening, I gulped down a recent interview of his with a joyous ferocity. One section struck an unexpectedly familiar chord.
That section talked about one thing makes e-book authors different from normal dead-tree authors: their personal interest in readers/customers. Since he has only Amazon as an intermediary between himself, and it's a thin layer, Howey has taken to forming relationships with some, conversing with tons.
In this, he reminds me of JMS, who during his Babylon 5 days, was a fixture on Usenet to talk with fans about the show.
But in another way, it reminded me of my own line of work: free/open-source software. When we build something, we put ourselves out there along with our code. Our names and much of our day-to-day workmanship are exposed directly to interested users. There is no opacity that comes from shrink-wrapping, lumping it together with other proprietary bits, hiding the innards, and selling it in a box (or on an app store). We show it all to our users; in return, they talk directly to us.
This has upsides and downsides, the former of which way outweigh the latter. When able, we can try one-on-one help, live on the ether. We can collect exact personal experiences, problem reports, wishes, without lossy intermediaries. When one of our favorite users has a problem, we feel personally motivated to jump in and fix it. When a user suggests a change, she becomes an informal colleague, and is endeared even more. When another succeeds in solving a problem with our widgets, we rejoice; when it fails, we feel guilt. Having exposed ourselves and our work, we cannot help but care.
This capacity for personal connection and the corollary pride in our work set our sector of the industry apart from the rest.
From the inconvenient self-awareness department, one William Dorland is briefly in the news, but it's hard to see why. After all, the learned gentleman is quoted as saying:
... it doesn't really matter what I think.
He's right.