All your heap are belong to us

This is a port and slight expansion of the ideas presented here.

The premise of that article is that underneath the interface provided by an application the handling of sensitive information is done in memory provided on the heap (via malloc/new). With that in mind, capturing the memory before it was released by the application would potentially expose hidden details. The system used in that article was OSX and the applications were Twitter-based but I decided to port to Linux and look at ssh.

First, the port:

---

#include <stdio.h>
#define __USE_GNU
#include <dlfcn.h>

void (*real_free)(void *);

void free (void * mem) {
    char buff[256] = {0}, * p = mem;
    int i = 0;

    if (! mem) { return; }

    while (*p) {
        buff[i++] = *p++;
        if (i > 254)
            break;
    }

    buff[i] = 0;
    fprintf (stderr, "[free] %s\n", buff);

    real_free = dlsym (RTLD_NEXT, "free");
    real_free (mem);
}

---

Nothing new here, just a version of free that will be interposed by this library. Compiling that and running the following:

LD_PRELOAD=/tmp/heapgrab.so ssh ezpz@sandbox 2>heapgrab.log

Produces a log with a substantial amount of information in it. However, the password is not included anywhere. It seems that ssh sanitizes buffers before freeing them - the next logical step is to provide a version of memset that does the same thing to try and capture where the memory is sanitized:

---

void* (*real_memset)(void*, int, size_t);

void * memset (void * mem, int c, size_t size) {
    char buff[256] = {0}, * p = mem;
    int i = 0;

    if (! mem ) { return; }

    while (*p) {
        buff[i++] = *p++;
        if (i > (size - 1) || i > 254)
            break;
    }

    buff[i] = 0;
    fprintf (stderr, "[memset] %s\n", buff);

    real_memset = dlsym(RTLD_NEXT, "memset");
    return real_memset (mem, c, size);
}

---

With that, our log now contains the following:

[free] publickey,password
[free] keyboard-interactive
[free] publickey
[memset] ezpz_awesome_password
[memset] xxxxx
[memset] ezpz_awesome_password

I've played with interpositioning a bit over the past few years but I never considered using it in exactly this way. Thanks to Joe Damato for the initial idea and original OSX code.

Anatomy of an update

I recently put ntrace up on github.

While I was doing testing for that version I saw my package manager blinking at me telling me I needed updates. I decided to take that as an opportunity to test ntrace on a more realistic use case (at the time I was just doing scp or iperf tests). Instead of using the Synaptic Package Manager GUI I opened up a terminal and used aptitude to do the update. Since I know nothing about how aptitude works, this was a good opportunity to see what ntrace could tell me.

Here was the command I ran:

LD_PRELOAD=./libntrace.so aptitude safe-upgrade

The update was small; it consisted of only 5 packages:

The following packages will be upgraded:
      libmozjs1d libsvn1 subversion xulrunner-1.9 xulrunner-1.9-gnome-support
    5 packages upgraded, 0 newly installed, 0 to remove and 7 not upgraded.
    Need to get 10.4MB of archives. After unpacking 8192B will be used.
    Do you want to continue? [Y/n/?]

After typing Y to continue the update completed without issue. I parsed the resulting output and compiled the following graph:

Interesting points:

• Between seconds 3 and 12 there is no activity. This is the time I was reading the screen before I confirmed and continued with the update.
• Each package was retrieved by it's own process. The dots are color-coded according to the PID that was associated with the traffic (see the legend).
• Packages are downloaded sequentially instead of in parallel.
• The long delay after 17 seconds is the time it took to actually install the updates on my system. The original process then communicates some more (presumably about the status of the children) and the update exits.
• The traffic patterns for the parent process are nearly identical at the front and back end of the communication. Maybe all details of the update are advertised at both ends instead of a diff? Dunno, but it is interesting.

This is how ntrace is useful to me: quick insight into application activity as it relates to the network.

As part of my testing I am doing performance impact analysis. Perhaps some of those details will appear here as well.

Intercepting Linux system calls: Part III

[Update] This code can now be found on github (ntrace)

In the previous post in this series, I described the similarities between strace and LD_PRELOAD and why you may opt to use one over the other. This is the final post in the series where I provide a situation where strace is inadequate and LD_PRELOAD becomes a more appropriate tool.

The contrived example provided earlier was trivial but this example is one that I have run across and was the catalyst for this set of posts. The situation I faced is that I had to understand how an application was interacting with the host system to communicate with the network. I needed a way to instrument this application to provide concise details about how changes being made at the transport layer were affecting the upper-layer protocols (i.e. performance).

This sounds straightforward considering the explanation of strace so far - and for the most part it is... but there are caveats. Let's consider the following piece of code:

/* 
 * reads from the net, writes to a pipe 
 */
void read_client (int sock, int fd) {
    ssize_t n = 0;
    char buff[2048] = {0};
    while ((n = recv (sock, buff, 2048, 0)) > 0) {
        /* write data to the pipe */
        write (fd, buff, n);
    }
}

The setup for this call is that there is a server that handles connections by setting up a pipe, forking a new process, and allowing the child process to read from the connection and write that data to the pipe. The parent then handles the data from the pipe and not directly from the network connection. The above call receives the network connection (sock) and write end of the pipe (fd) as parameters. So far, there is nothing that precludes us from using strace with the proper flags to monitor the behavior of this process. For example:

strace -f -e trace=network -o trace.log ./recv_example

provides the following bit of output

13328 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
13328 bind(3, {sa_family=AF_INET, sin_port=htons(41477), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
13328 listen(3, 10)                     = 0
13328 accept(3, {sa_family=AF_INET, sin_port=htons(36412), sin_addr=inet_addr("127.0.0.1")}, [16]) = 4
13362 recv(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2048, 0) = 2048
13362 recv(4, "", 2048, 0)              = 0
13328 --- SIGCHLD (Child exited) @ 0 (0) ---

We can see that strace only caught the network-related calls, followed the fork, realized the recv call in the child, and that the server received 2048 bytes from the network. This would be enough to accomplish the goal... but there are caveats.

As it turns out, not everyone follows the same approach when reading/writing to network sockets. For instance, the function described above could have been written using the read system call instead and would perform in exactly the same way. Consider the following change:

--- read_example.c 2010-12-03 10:44:32.000000000 -0500
+++ recv_example.c 2010-12-03 10:44:43.000000000 -0500
@@ -18,7 +18,7 @@
 void read_client (int sock, int fd) {
     ssize_t n = 0;
     char buff[2048] = {0};
-    while ((n = read (sock, buff, 2048)) > 0) {
+    while ((n = recv (sock, buff, 2048, 0)) > 0) {
         /* write data to the pipe */
         write (fd, buff, n);
     }

Now our strace approach gets slightly more complicated. Using the exact same flags as above our log now contains the following after a run:

14126 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
14126 bind(3, {sa_family=AF_INET, sin_port=htons(41477), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
14126 listen(3, 10)                     = 0
14126 accept(3, {sa_family=AF_INET, sin_port=htons(36418), sin_addr=inet_addr("127.0.0.1")}, [16]) = 4
14126 --- SIGCHLD (Child exited) @ 0 (0) ---

Notice the absence of the read call? According to -e trace=network, read is not a network-related system call. Fine. Easy fix, we just add the read call to the list of calls to trace and be done with it.

strace -f -e trace=network,read -o trace.log ./recv_example

Unfortunately, that only further muddies the water.

14130 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\200\257\274\0004\0\0\0"..., 512) = 512
14130 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
14130 bind(3, {sa_family=AF_INET, sin_port=htons(41477), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
14130 listen(3, 10)                     = 0
14130 accept(3, {sa_family=AF_INET, sin_port=htons(36419), sin_addr=inet_addr("127.0.0.1")}, [16]) = 4
14132 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2048) = 2048
14132 read(4, "", 2048)                 = 0
14130 --- SIGCHLD (Child exited) @ 0 (0) ---
14130 read(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2048) = 2048
14130 read(5, "", 2048)                 = 0

Now we are getting all of the read calls including those related to loading ELF binaries, reading from the pipe in the parent process, and the network call. This magnifies as you consider the number of ways these calls can be arranged.

What this is really telling us is that the information we desire is buried in context - it dependent upon state.

This is where LD_PRELOAD with a shim library becomes appropriate. What we'd really like to do is take every way that a developer can interact with a network file descriptor and monitor those calls but with the added benefit of knowing something about the file descriptor itself. In the previous output we could build the state from the trace - parse out the return values for the system calls, associate them with a particular behavior, etc.  That's not entirely true since, at that point, we would need to trace all calls (pipe, for instance) but it would get us close. That is error prone and tedious. If the format of the output changes or the flags to strace weren't just so we'd need to adjust.

It is much better to have that state build up with the execution of the program and remain resident until the program exits. The solution presented here is well beyond the needs of this small example but it exposes how we can overcome the limitations of strace when the occasion calls for it.

If we use this shim library tool on the second program above (the one using read instead of recv) we get two files - one for each process: 14228.log and 14230.log. In this case, 14228 is the parent process and reads from the pipe while 14230 is reading from the network and writing to the pipe. These files recap the overall activity of each process and solve the issue exactly. We now see what operations are related to the network - the top of each file provides call-by-call details - and we don't need to worry about changes to external flags or output format to ensure proper operation.

14228.log

call,fd,pid,seq,time,size,recv_so_far,send_so_far

Network totals: (0, 0)
     read : 0 (0)
     recv : 0 (0)
 recvfrom : 0 (0)
  recvmsg : 0 (0)
    write : 0 (0)
     send : 0 (0)
   sendto : 0 (0)
  sendmsg : 0 (0)

Pipe:14228:8 (2048,0)
Pipe totals: (2048, 0)
     read : 2 (2048)
     recv : 0 (0)
 recvfrom : 0 (0)
  recvmsg : 0 (0)
    write : 0 (0)
     send : 0 (0)
   sendto : 0 (0)
  sendmsg : 0 (0)

Disk totals: (0, 0)
     read : 0 (0)
     recv : 0 (0)
 recvfrom : 0 (0)
  recvmsg : 0 (0)
    write : 0 (0)
     send : 0 (0)
   sendto : 0 (0)
  sendmsg : 0 (0)

14230.log

call,fd,pid,seq,time,size,recv_so_far,send_so_far
read,7,14230,0,1291401018.139170,2048,2048,0
read,7,14230,0,1291401018.139199,0,2048,0

Network:14230:7 (2048,0)
Network totals: (2048, 0)
     read : 2 (2048)
     recv : 0 (0)
 recvfrom : 0 (0)
  recvmsg : 0 (0)
    write : 0 (0)
     send : 0 (0)
   sendto : 0 (0)
  sendmsg : 0 (0)

Pipe:14230:9 (0,2048)
Pipe totals: (0, 2048)
     read : 0 (0)
     recv : 0 (0)
 recvfrom : 0 (0)
  recvmsg : 0 (0)
    write : 1 (2048)
     send : 0 (0)
   sendto : 0 (0)
  sendmsg : 0 (0)

Disk totals: (0, 0)
     read : 0 (0)
     recv : 0 (0)
 recvfrom : 0 (0)
  recvmsg : 0 (0)
    write : 0 (0)
     send : 0 (0)
   sendto : 0 (0)
  sendmsg : 0 (0)

We can also get an strace-like output that allows us to find out exactly what is happening during execution. This is helpful to understand the internals of the program and is exactly what strace provides but we get it (and the added state) for free. Notice in the output below that each operation on a file descriptor is classified (NET vs. PIPE).

** DEBUG (14228) ** Initialized the debug channel
 ** DEBUG (14228) **  Created process state 0x8e51008. pid: 14228, ppid: 4285, thid: -1208371520
 ** DEBUG (14228) **  Setting up traffic on fd 0
 ** DEBUG (14228) **   Details:
 ** DEBUG (14228) **   Disk oriented
 ** DEBUG (14228) **  Setting up traffic on fd 1
 ** DEBUG (14228) **   Details:
 ** DEBUG (14228) **   Disk oriented
 ** DEBUG (14228) **  Setting up traffic on fd 2
 ** DEBUG (14228) **   Details:
 ** DEBUG (14228) **   Disk oriented
 ** DEBUG (14228) ** socket (2, 1, 0) = 6
 ** DEBUG (14228) **  Setting up traffic on fd 6
 ** DEBUG (14228) **   Details:
 ** DEBUG (14228) **   Network oriented
 ** DEBUG (14228) ** bind (6, 0xbfeeae20, 16) = 0
 ** DEBUG (14228) ** accept (6, 0xbfeeae10, 16) = 7
 ** DEBUG (14228) **  Setting up traffic on fd 7
 ** DEBUG (14228) **   Details:
 ** DEBUG (14228) **   Network oriented
 ** DEBUG (14228) ** pipe ([8, 9]) = 0
 ** DEBUG (14228) **  Setting up traffic on fd 8
 ** DEBUG (14228) **   Details:
 ** DEBUG (14228) **   Pipe oriented
 ** DEBUG (14228) **  Setting up traffic on fd 9
 ** DEBUG (14228) **   Details:
 ** DEBUG (14228) **   Pipe oriented
 ** DEBUG (14230) ** Initialized the debug channel
 ** DEBUG (14230) **  Copying process details from parent 14228 (getppid: 14228)
 ** DEBUG (14230) **  Rehashing fd 0 (disk)
 ** DEBUG (14230) **  Rehashing fd 1 (disk)
 ** DEBUG (14230) **  Rehashing fd 2 (disk)
 ** DEBUG (14230) **  Rehashing fd 6 (net)
 ** DEBUG (14230) **  Rehashing fd 7 (net)
 ** DEBUG (14230) **  Rehashing fd 8 (pipe)
 ** DEBUG (14230) **  Rehashing fd 9 (pipe)
 ** DEBUG (14230) ** close (8) = 0
 ** DEBUG (14230) **  (Exiting fd 8)
 ** DEBUG (14230) **   network     : no
 ** DEBUG (14230) **   disk        : no
 ** DEBUG (14230) **   pipe        : yes
 ** DEBUG (14230) **   active      : yes
 ** DEBUG (14230) **   has_hb      : no
 ** DEBUG (14230) ** [ NET] read (7, 0xbfee9dc0, 2048) = 2048
 ** DEBUG (14230) **  fd 7 used for the first time
 ** DEBUG (14230) **  spawing thread for fd 7
 ** DEBUG (14230) **  Detail
 ** DEBUG (14230) **   delay (in usec)    : 1000000
 ** DEBUG (14230) **  thread created: -1208374368
 ** DEBUG (14230) ** [PIPE] write (9, 0xbfee9dc0, 2048) = 2048
 ** DEBUG (14230) ** [ NET] read (7, 0xbfee9dc0, 2048) = 0
 ** DEBUG (14230) ** close (9) = 0
 ** DEBUG (14230) **  (Exiting fd 9)
 ** DEBUG (14230) **   network     : no
 ** DEBUG (14230) **   disk        : no
 ** DEBUG (14230) **   pipe        : yes
 ** DEBUG (14230) **   active      : yes
 ** DEBUG (14230) **   has_hb      : no
 ** DEBUG (14230) **  [atexit]
 ** DEBUG (14230) ** _exit (0) = ...
 ** DEBUG (14230) **  Cleanup. Stopping any active threads
 ** DEBUG (14230) **  < joining with thread -1208374368 ... >
 ** DEBUG (14228) ** close (9) = 0
 ** DEBUG (14228) **  (Exiting fd 9)
 ** DEBUG (14228) **   network     : no
 ** DEBUG (14228) **   disk        : no
 ** DEBUG (14228) **   pipe        : yes
 ** DEBUG (14228) **   active      : yes
 ** DEBUG (14228) **   has_hb      : no
 ** DEBUG (14230) **  < ... join complete >
 ** DEBUG (14228) ** [PIPE] read (8, 0xbfeea600, 2048) = 2048
 ** DEBUG (14228) ** [PIPE] read (8, 0xbfeea600, 2048) = 0
 ** DEBUG (14228) ** close (8) = 0
 ** DEBUG (14228) **  (Exiting fd 8)
 ** DEBUG (14228) **   network     : no
 ** DEBUG (14228) **   disk        : no
 ** DEBUG (14228) **   pipe        : yes
 ** DEBUG (14228) **   active      : yes
 ** DEBUG (14228) **   has_hb      : no
 ** DEBUG (14228) ** close (7) = 0
 ** DEBUG (14228) **  (Exiting fd 7)
 ** DEBUG (14228) **   network     : yes
 ** DEBUG (14228) **   disk        : no
 ** DEBUG (14228) **   pipe        : no
 ** DEBUG (14228) **   active      : yes
 ** DEBUG (14228) **   has_hb      : no
 ** DEBUG (14228) ** close (6) = 0
 ** DEBUG (14228) **  (Exiting fd 6)
 ** DEBUG (14228) **   network     : yes
 ** DEBUG (14228) **   disk        : no
 ** DEBUG (14228) **   pipe        : no
 ** DEBUG (14228) **   active      : yes
 ** DEBUG (14228) **   has_hb      : no
 ** DEBUG (14228) **  [atexit]
 ** DEBUG (14228) ** _exit (0) = ...
 ** DEBUG (14228) **  Cleanup. Stopping any active threads

Intercepting Linux system calls: Part II

[Update] This code can now be found on github (ntrace)

Continuing from the first part of this discussion, I thought it would be best to first show what strace does and how LD_PRELOAD compares to that before continuing on to a full-blown example of using one over the other.

strace
strace is a utility that either attaches to an already running process or spawns an entirely new process and monitors that process' system calls and signals. This is done via ptrace and thus provides an almost scary level of control over the process being monitored. This is precisely why I prefer to use strace over LD_PRELOAD in most cases.

LD_PRELOAD
LD_PRELOAD is an environment variable that can contain a custom library to be loaded before others when invoking a program. This allows for behaviors such as intercepting library calls (e.g. libc) and invoking custom behavior around or instead of the intended target code. LD_PRELOAD does not allow a user (without extended effort) to poke at the registers and data sections of a running process or to receive signals destined to the process.

To give an idea of how you might use each of these in context, lets say that you have a program that will print updates to the screen whenever it receives events internally. As a matter of black-boxing that application, you would like to know how often these events are occurring but you do not have access to the source code and there is no timing information other than some text output to the screen. For example:

ezpz@sandbox:~/blog > ./event_handler
updated again
updated again
updated again
updated again
...

All you can see is a stream of notifications. What you'd like to see, however, is some indication of time with (or instead of) the meaningless update. strace is perfect for this as it gets notified each time a write is about to occur and prints a timestamp along with that data. Here is an example that prefixes traced calls with a seconds/microseconds timestamp and only responds to the write system call.

The command is:

strace -ttt -e trace=write -o strace.log ./event_handler

That command produces a log file with the following contents:

1291244916.592714 write(1, "updated again\n"..., 14) = 14
1291244917.024000 write(1, "updated again\n"..., 14) = 14
1291244917.217090 write(1, "updated again\n"..., 14) = 14
1291244917.354294 write(1, "updated again\n"..., 14) = 14
...

Now you can easily see when each event fires and with a simple script could determine with what frequency these events most often occur.

Similarly, you can use LD_PRELOAD to do this. In this particular case there is significantly more work to be done (another reason to opt for strace first) but bear with me for the illustration.

In the LD_PRELOAD case you need to provide an shared library that can be loaded and used in place of the libraries you want to modify. Let's set that up: first, the interception code:

#define _GNU_SOURCE
#include <sys/time.h>
#include <stdio.h>
#include <dlfcn.h>

/*
 * Use the same signature as libc's puts when defining our interceptor
 * and function pointer
 *  int puts(const char *s);
 */
typedef int (*libc_puts)(const char *);

/*
 * Provide our version of puts here
 */
int puts (const char *s) {
    /* grab the actual puts */
    libc_puts original = dlsym (RTLD_NEXT, "puts");

    /* prefix the output with our timestamp */
    struct timeval tv;
    gettimeofday (&tv, 0);
    printf ("[%ld.%06ld] ", tv.tv_sec, tv.tv_usec);

    /* pass the arguments through to the libc call */
    return original(s);
}

Once that is built you can use the shim by

ezpz@sandbox:~/blog > LD_PRELOAD=./shim.so ./event_handler

which yields

ezpz@sandbox:~/blog > LD_PRELOAD=./shim.so ./event_handler
[1291246609.278321] updated again
[1291246609.709342] updated again
[1291246609.902186] updated again
[1291246610.039169] updated again
...

So you have an equally viable solution in either case. The point here was not necessarily to show why either of the two of these methods is better than the other in this contrived example but to expose the fact that you can do similar things with each. The strace solution here does not allow for injecting your own code into a running process but it does capture the exact thing you want without the overhead of having to build a shared library to get it done.

I'll continue next time with why you might need to modify program behavior to get data that is just not available with strace.

Intercepting Linux system calls: Part I

[Update] This code can now be found on github (ntrace)

Working below the application layer affords me the luxury of not having to worry about implementation details as they relate to the hosting system... mostly. Sometimes, however, I am forced to have to either measure or dictate application behavior. For the most part the driving force here is mapping network effects to application artifacts.

When this situation arises I always task myself with finding the shortest path to implementation. Usually, the options are roughly:

• Use an existing logging facility within the application
• Look through and edit source code (when available)
• Use a utility such as strace/ltrace
• Shim the application to 'spy' on or 'touch' the application

I don't regularly come across programs that offer the type of logging needed to gain the insight required to pinpoint absolute performance. This is understandable since any logging I usually provide (if any) is designed to allow me to reverse-engineer any problems with the product without having to run it myself.

Source code browsing holds it's own set of problems. First, reading code is much harder than writing it and grokking another's thought process through that code takes an additional mental leap once you do get familiar. Matters worsen when there is invalid or missing comments and/or poorly written code. These problems are time consuming and entirely dependent on having the source in the first place. With very few exceptions I avoid this approach.

The most common solution I find to be appropriate is to use strace (or ltrace) and parse the output. There are few situations where the vast functionality of a tool like strace will not suffice, but these situation do come up. One such situation is the case when you want to use strace with the -e trace=network flag but need the added benefit of having context regarding the calls being made. strace is only going to give you a fixed set of calls traced and if the context you need is born or modified outside of that scope you need to engineer a more specific solution.

In the next set of posts I will walk through a complete solution to the above problem using the linux LD_PRELOAD environment variable.