Project

General

Profile

Bug #561

Under certain conditions, a user-space trace may overwrite itself

Added by Daniel U. Thibault over 6 years ago. Updated over 4 years ago.

Status:
Confirmed
Priority:
Low
Assignee:
-
Target version:
Start date:
06/13/2013
Due date:
% Done:

0%

Estimated time:

Description

Suppose we do this:

$ sudo -H lttng create asession
$ sudo -H lttng enable-event -a -u
$ sudo -H lttng start

And suppose we have an application that has been instrumented with some user-space tracepoint provider. Suppose the application's main loop is something like this (borrowed from easy-ust):

int main(int argc, char **argv)
{
    int i = 0;
    char themessage[20]; //Can hold up to "Hello World 9999999\0" 
    void *libtp_handle;

    libtp_handle = dlopen("./libtp.so", RTLD_LAZY);

    fprintf(stderr, "sample starting\n");
    for (i = 0; i < 10000; i++) {
        if ((i == 3333) && (libtp_handle)) dlclose(libtp_handle);
        if (i == 6666) libtp_handle = dlopen("./libtp.so", RTLD_LAZY);
        sprintf(themessage, "Hello World %u", i);
        tracepoint(sample_component, event, themessage);
        usleep(1);
    }
    fprintf(stderr, "sample done\n");

    if (libtp_handle) return dlclose(libtp_handle);
    return 0;
}

The trace produced will capture two separate processes: the first one for the app's first 3333 loops, the second for the app's last 3333 loops. This is because the app will register itself as a user-space event source, then withdraw its registration only to later re-register.

As it happens, most of the time the two third-runs will be a second apart, resulting in the trace holding two pid subdirectories: say sample-17541-20130613-135148 and sample-17541-20130613-135149. But now and again both processes will be within the same one-second window, and the trace will thus contain only one pid subdirectory, say sample-17541-20130613-135151 ---the problem is that the app's first 3333 loops were written to disk and then the last 3333 loops were written to the same file.

This only gets worse if the dlopen/dlclose calls are more tightly packed in time.

The bug boils down to this: once a tracing session detects a new process client, lttng should detect path collisions and correct for them. One solution would be to have a trace's path be:

tracepath/ust/pid/process_name-VPID-yyyymmdd-hhmmss[-n]/

In my example, the first 3333 loops would go to tracepath/ust/pid/sample-17541-20130613-135151 and the last 3333 loops to tracepath/ust/pid/sample-17541-20130613-135151-1

I suppose a similar problem can happen with per-uid traces.

#1

Updated by Daniel U. Thibault over 6 years ago

It may seem to make more sense to have the last 3333 loops append to the existing files when the timestamp is within the same second window. But this would cause two problems.

The first is a lack of predictability: a process like this that runs for a long time would create multiple pid subdirectories spread one second apart, but some of the subdirectories would contain more than one "run". Not a very serious problem, but it just feels wrong.

The second is more serious: nothing prevents the app from dlclosing one trace provider dynamic library and then dlopening another one which could put a completely different payload in the event record. As long as the tracepoint() call has the same provider name, tracepoint name, and arguments, nothing in lttng prevents this, as far as I know (I haven't tried it yet).

#2

Updated by Daniel U. Thibault over 6 years ago

Just a note to confirm that it is possible for an instrumented application to switch its trace provider dynamic library using dlclose and dlopen. A single tp.h is used in the application (which describes a first event payload). This trace provider is packaged in a first library, libtp.so. A modified tp2.h is then used to create libtp2.so. Same provider name, event name, tracepoint arguments, etc. The only difference is in the payload definition, which switches from a ctf_string to a ctf_integer.

This causes no problems to lttng or babeltrace, since the resumed trace ends up in a separate subdirectory with a distinct metadata file (correctly describing the changed payload). babeltrace switches between the two types of payloads without missing a beat. (The story would be different for some client of babeltrace's output, which may not accept the change in trace event format)

This confirms that a "resumed" trace cannot append its events to its "original" channel files: the metadata need to be different.

#3

Updated by David Goulet over 6 years ago

  • Status changed from New to Confirmed
  • Priority changed from Normal to Low
#4

Updated by Jérémie Galarneau over 4 years ago

  • Target version set to Wishlist

Also available in: Atom PDF