D.2 Remote Logging

The local logging facility discussed in Section D.1 is useful when the message to be logged is created in pieces that need to be logged together. However, the local logging facility can be used only by collections of single-threaded processes on the same host. The remote logging facility is meant to be used in a multithreaded environment or one in which processes on multiple machines are cooperating or communicating.

Programs that depend on concurrency (primarily those that fork children, create multiple threads, or that depend on communicating processes) are often difficult to understand and debug. Debuggers for multithreaded programs are not generally available, let alone ones that can unify the debugging of communicating processes running on different machines, possibly on incompatible hardware.

The logging facility described here allows for instrumenting code in a simple way to log events. The logged events are sent to a possibly remote machine and gathered for analysis. Events are timestamped according to when they arrive at the receiving machine. If the variance of network delays are small compared with the granularity of the logging, these times acceptably indicate the sequence of events that occur in logged programs. Optionally , messages can be timestamped with the time they were generated. This is useful if all messages are logged from the same host or from hosts with synchronized clocks.

The underlying philosophy of the logging facility is to provide a simple, familiar C-language-based interface that can be mastered in a few minutes. Most of the complication is moved to the receiving end, which has a GUI for ease of use.

The facility is thus broken into two independent parts , the C language interface which runs in a UNIX environment, and a Java-based GUI receiving module that can be run on any system having a Java runtime environment.

The C language interface is modeled on the C language FILE pointer I/O interface and has functions corresponding to fopen , fclose and fprintf . These are called lopen , lclose and lprintf , respectively. Three other functions, lprintfg , lgenerator and lsendtime , allow more control over how the logged data is labeled.

The logging functions return NULL ( lopen ) or “1 (all others) on error. Do not use errno with any of the functions in the library. By default, these functions do not print error messages. To simplify debugging, they send error messages to standard error if in debugging mode. You can enter debugging mode by calling ldebug(1) and exit debugging mode by calling ldebug(0) . Alternatively, you can turn on debugging by compiling with LDEBUGGING defined.

To use the logging facility, include rlogging.h , shown in Program D.3, and compile with rlogging.c , shown in Program D.4. The former file contains the typedefs and prototypes , and the latter contains the code. The program must also be linked with restart.c , described in Appendix B, and with uici.c and uiciname.c , described in Appendix C. If the program is used in a multithreaded environment, the constant LUSETHREAD should be defined. The simplest way to do this is with a compiler option. Many compilers support the use of -DLUSETHREAD option to define LUSETHREAD at compile time.

Program D.3 rlogging.h

The header file for the remote logging module .

 #define LFILE_GENLENGTH 16 typedef struct LFILE {    int id;    int fd;    int tmode;    char gen[LFILE_GENLENGTH]; } LFILE; LFILE *lopen(char *host, int port); int lclose(LFILE *mf);                    /* not thread safe */ void ldebug(int debug); int lprintf(LFILE *mf, char *fmt, ...); int lprintfg(LFILE *mf, char *gen, char *fmt, ...); int lgenerator(LFILE *mf, char *gen); int lsendtime(LFILE *mf); 

Program D.4 rlogging.c

C source for the logging module .

 #include <errno.h> #include <limits.h> #include <stdio.h> #include <stdlib.h> #include <stdarg.h> #include <string.h> #include <time.h> #include <unistd.h> #include <sys/time.h> #ifdef LUSETHREAD #include <pthread.h> #endif #include "restart.h" #include "rlogging.h" #include "uici.h" #define DEFAULT_HOST "localhost" #define DEFAULT_PORT 20100 #define LOGGING_BUFSIZE PIPE_BUF #define LOGGING_GENMAX 50 /* Note: LOGGING_BUFSIZE must be at most PIPE_BUF */ static int nextID = 0; #ifdef LDEBUGGING static int ldebug_flag = 1; #else static int ldebug_flag = 0; #endif #ifdef LUSETHREAD static pthread_mutex_t ctime_mutex = PTHREAD_MUTEX_INITIALIZER; static pthread_mutex_t generator_mutex = PTHREAD_MUTEX_INITIALIZER; static pthread_mutex_t ID_mutex = PTHREAD_MUTEX_INITIALIZER; #endif /* Turn on debugging if debug = 1                                     */ void ldebug(int debug) {    ldebug_flag = debug; } static long get_threadid() { #ifdef NOTHREADID    return 0L; #else #ifdef LUSETHREAD    return (long)pthread_self(); #else    return 1L; #endif #endif } /* Expand the generator, gen_fmt, into the buffer gen that has size gensize.  * return 0 if fits, 1 if it does not.  * %p is converted to process ID.  * %t is converted to thread ID.  * if (gen_fmt[0] == 0) then just then pid.tid is used.  * at most one %p and one %t are allowed. */ static int expand_gen(const char *gen_fmt, char *gen, int gensize) {    int needed;    char *pp;    char *pt;    pp = strstr(gen_fmt, "%p");    pt = strstr(gen_fmt, "%t");    if (gen_fmt[0] == 0) {                           /* Use default generator */ #ifdef NOTHREADID       needed = snprintf(gen, gensize, "%ld", (long)getpid()); #else #ifdef LUSETHREAD       needed = snprintf(gen, gensize, "%ld.%ld", (long)getpid(),                         get_threadid()); #else       needed = snprintf(gen, gensize, "%ld", (long)getpid()); #endif #endif    }    else if ((pt == NULL) && (pp == NULL))       needed = snprintf(gen, gensize, "%s", gen_fmt);    else if (pt == NULL)       needed = snprintf(gen, gensize, "%.*s%ld%s", (int)(pp-gen_fmt), gen_fmt,                         (long)getpid(), pp+2);    else if (pp == NULL) {       needed = snprintf(gen, gensize, "%.*s%ld%s", (int)(pt-gen_fmt), gen_fmt,                         get_threadid(), pt+2);       }    else if (pp < pt) {       needed = snprintf(gen, gensize, "%.*s%ld%.*s%ld%s",                        (int)(pp-gen_fmt), gen_fmt, (long)getpid(),                        (int)(pt-pp-2), pp+2, get_threadid(), pt+2);    }    else {       needed = snprintf(gen, gensize, "%.*s%ld%.*s%ld%s", (int)(pt-gen_fmt),                      gen_fmt, get_threadid(), (int)(pp-pt-2), pt+2,                      (long)getpid(), pp+2);    }    if (needed >= gensize)       return 1;    return 0; } #define RWBUFSIZE PIPE_BUF /* Read from infd and write to outfd until an error or end-of-file occurs */ static void readwriteall(int infd, int outfd) {    char buf[RWBUFSIZE];    int bytes_read;    while ((bytes_read = r_read(infd, buf, RWBUFSIZE)) > 0) {       if (r_write(outfd, buf, bytes_read) != bytes_read) {          if (ldebug_flag)             fprintf(stderr, "Pipe write error\n");          close(infd);          close(outfd);          return;       }    }    if (bytes_read < 0) {       if (ldebug_flag)          fprintf(stderr, "Pipe read error\n");    }    close(infd);    close(outfd); } /* Create a pipe and a child process.  * All output is sent to the pipe.  * The child process reads from the pipe and outputs to the network. */ static void go_through_pipe(LFILE *mf) {    int childpid;    int fds[2];    if (pipe(fds) < 0) {       if (ldebug_flag)          fprintf(stderr, "Pipe creation failed\n");       return;    }    childpid = fork();    if (childpid < 0) {       if (ldebug_flag)          fprintf(stderr, "Fork failed\n");       close(fds[0]);       close(fds[1]);       return;    }    if (childpid == 0) {                                        /* child code */       close(fds[1]);       readwriteall(fds[0], mf->fd);       exit(0);    }    close(fds[0]);    close(mf->fd);    mf->fd = fds[1]; } /* Set the parameters to the current time  * return 0 on success and 1 on failure. */ static int set_times(unsigned long *secp, unsigned long *usecp) {    struct timeval tp;    if (gettimeofday(&tp, NULL))       return 1;    *secp = (unsigned long)tp.tv_sec;    *usecp = (unsigned long)tp.tv_usec;    return 0; } /* Create a string representing the time given by sec and usec in the  *    buffer buf.  This assumes that buf is large enough.  * Return 0 on success and 1 on failure. */ static int make_time_string(char *buf, unsigned long sec, unsigned long usec) {    time_t clock;    double fract;    char *tm;    clock = (time_t)sec;    fract = usec/1000000.0;    sprintf(buf+7, "%5.3f", fract); #ifdef LUSETHREAD    if (pthread_mutex_lock(&ctime_mutex))       return 1; #endif    tm = ctime(&clock);    strncpy(buf,tm+11,8); #ifdef LUSETHREAD    if (pthread_mutex_unlock(&ctime_mutex))       return 1; #endif    return 0; } /* Log the string given by the last two parameters.  * Use the given generator.  * Return 0 on success and -1 on failure. */ static int lprintfgen(LFILE *mf, char *gen, char *fmt, va_list ap) {    int blen;                                          /* size of data buffer */    char buf[LOGGING_BUFSIZE];    char buftemp[LOGGING_BUFSIZE];    char genbuf[LOGGING_GENMAX];    int ret;    unsigned long sec;    char timebuf[13];    char *timep;    char timesbuf[20];                      /* holds seconds and microseconds */    unsigned long usec;    int written;    if (mf==NULL) {       if (ldebug_flag)          fprintf(stderr, "lprintf called with NULL first parameter\n");       return -1;    }    if ( (mf->tmode)  (strstr(fmt, "%t") != NULL) )       if (set_times(&sec, &usec) != 0) {          if (ldebug_flag)             fprintf(stderr, "Error getting current time\n");          return -1;       }    if (mf->tmode)       sprintf(timesbuf, "%lu;%lu;", sec, usec);    else       timesbuf[0] = 0;    timep = strstr(fmt, "%t");    if (timep != NULL) {       if (make_time_string(timebuf, sec, usec) != 0) {          if (ldebug_flag)             fprintf(stderr, "Error making time string in lprintf\n");          return -1;       }       if (strlen(fmt) + 13 >= LOGGING_BUFSIZE) {             fprintf(stderr, "Format string is too long\n");          return -1;       }       sprintf(buf, "%.*s%s%s", (int)(timep-fmt), fmt, timebuf, timep+2);       ret = vsnprintf(buftemp, LOGGING_BUFSIZE, buf, ap);    }    else       ret = vsnprintf(buftemp, LOGGING_BUFSIZE, fmt, ap);    if ((ret < 0)  (ret >= LOGGING_BUFSIZE)) {        if (ldebug_flag)           fprintf(stderr, "Error in lprintf format string\n");        return -1;    }    if (expand_gen(gen, genbuf, LOGGING_GENMAX) != 0) {        if (ldebug_flag)           fprintf(stderr, "Generator info does not fit\n");    }    blen = strlen(buftemp) + strlen(genbuf) + strlen(timesbuf);    ret = snprintf(buf, LOGGING_BUFSIZE, "%d:%s%s;%s", blen+1,                   timesbuf, genbuf, buftemp);    if (ret >= LOGGING_BUFSIZE) {        if (ldebug_flag)           fprintf(stderr, "Error in lprintf: size too large to fit\n");        return -1;    }    while (written = write(mf->fd, buf, ret), written == -1 && errno == EINTR) ;    if (written != ret) {       if (ldebug_flag)          fprintf(stderr, "lprintf error writing to pipe\n");       return -1;    }    return 0; } /* Open a connection to the given host and port for logging.  * If host is NULL, use the environment variable LOGGINGHOST if it is set;  *    otherwise, use the host "localhost".  * If port is 0, use the environment variable LOGGINGPORT if it is set;  *    otherwise, use the default port DEFAULT_PORT.  * Return a pointer to an LFILE if successful, or NULL if unsuccessful. */ LFILE *lopen(char *host, int port) {    int fd;    LFILE *mf;    char *portstr;    if (host == NULL) {       host = getenv("LOGGINGHOST");       if (host == NULL)          host = DEFAULT_HOST;    }    if (port <= 0) {       portstr = getenv("LOGGINGPORT");       if (portstr == NULL)          port = DEFAULT_PORT;       else          port = atoi(portstr);    }    fd = u_connect(port, host);    if (fd < 0) {       if (ldebug_flag)          fprintf(stderr, "Connection failed to host %s on port %d\n",                  host,port);       return NULL;    }    mf = (LFILE *)malloc(sizeof(LFILE));    if (mf == NULL) {       if (ldebug_flag)          fprintf(stderr, "Memory allocation error for lopen\n");       return NULL;    } #ifdef LUSETHREAD    if (pthread_mutex_lock(&ID_mutex))       return NULL; #endif    mf->id = nextID++; #ifdef LUSETHREAD    if (pthread_mutex_unlock(&ID_mutex))       return NULL; #endif    mf->fd = fd;    mf->tmode = 0;    mf->gen[0] = 0;    go_through_pipe(mf); #ifdef LSENDTIME    lsendtime(mf); #endif    return mf; } /* Close the connection corresponding to mf.  * Return 0 on success and -1 on failure. */ int lclose(LFILE *mf) {    if (mf == NULL) {       if (ldebug_flag)          fprintf(stderr, "lclose called with NULL parameter\n");       return -1;    }    if (close(mf->fd) == -1) {       if (ldebug_flag)          fprintf(stderr, "lclose failed to close the connection\n");    }    free(mf);    return 0; } /* Log the given string, using the default generator.  * The parameters are similar to those of printf.  * Return 0 on success and -1 on failure. */ int lprintf(LFILE *mf, char *fmt, ...) {    char genbuf[LFILE_GENLENGTH];    va_list ap;    if (mf==NULL) {       if (ldebug_flag)          fprintf(stderr, "lprintf called with NULL first parameter\n");       return -1;    }    va_start(ap, fmt); #ifdef LUSETHREAD    if (pthread_mutex_lock(&generator_mutex))       return -1; #endif    strcpy(genbuf, mf->gen); #ifdef LUSETHREAD    if (pthread_mutex_unlock(&generator_mutex))       return -1; #endif    return lprintfgen(mf, genbuf, fmt, ap); } /* Log the given string, using the given generator.  * The parameters are similar to those of printf.  * Return 0 on success and -1 on failure. */ int lprintfg(LFILE *mf, char *gen, char *fmt, ...) {    va_list ap;    if (mf==NULL) {       if (ldebug_flag)          fprintf(stderr, "lprintf called with NULL first parameter\n");       return -1;    }    va_start(ap, fmt);    return lprintfgen(mf, gen, fmt, ap); } /* Set the default generator to the given one.  * Return 0 on success and -1 on failure. */ int lgenerator(LFILE *mf, char *gen) {    if (mf == NULL)       return -1;    if (gen == NULL)       mf->gen[0] = 0;    if (strlen(gen) >= LFILE_GENLENGTH)       return -1; #ifdef LUSETHREAD    if (pthread_mutex_lock(&generator_mutex))       return -1; #endif    strcpy(mf->gen,gen); #ifdef LUSETHREAD    if (pthread_mutex_unlock(&generator_mutex))       return -1; #endif    return 0; } /* Send the local time with each logged message.  * Return 0 on success and -1 on failure. */ int lsendtime(LFILE *mf) {    if (mf == NULL)       return -1;    mf->tmode = 1;    if (r_write(mf->fd, "-", 1) < 0) {       if (ldebug_flag)          fprintf(stderr, "Pipe write error\n");       return -1;    }    return 0; } 

D.2.1 Use of the remote logging facility

This section briefly describes how to use the remote logging facility. For a more detailed discussion, see [98]. A complete user 's guide and all the programs are available online [99].

The logging GUI must be started first. It can be run on any host with a Java runtime environment. The GUI listens for connections using TCP. If no port number is specified on the command line, the GUI takes the port number from the environment variable LOGGINGPORT or uses a default port number if this environment variable is not defined.

The program that is being logged must be linked with the restart library, the UICI library, the UICI name resolution library and the logging library. The only functions that need to be directly accessed are given in Program D.3.

First, make a connection to the GUI by using lopen . The parameters are a host name and a port number. If the host name is NULL or the port number is less than or equal to zero, lopen uses the values of the environment variables ( LOGGINGPORT and LOGGINGHOST ). If these environment variables are undefined, lopen uses default values. The lopen function returns a pointer of type LFILE that is used as a parameter to the other logging functions. You can then set optional behavior with the lsendtime and lgenerator functions. Logging is done with the lprintf and lprintfg functions, which have syntax similar to that of fprintf .

The implementation assumes that the thread ID can be cast to a long in a meaningful way. If this is not the case, the function get_threadid might have to be changed. Alternatively, when using the remote logger with threads, compile with NOTHREADID defined, and the thread ID will not be used as part of the generator.

Details of these functions are given below.

 LFILE *lopen(char *host, int port); 

open a connection to the logging GUI. The host parameter is the name of the host on which the GUI is running, and port is the port number that the GUI is using. If host is NULL , lopen takes the host name from the environment variable LOGGINGHOST . If LOGGINGHOST is not set, lopen uses the default host name localhost . If port is less than or equal to 0, lopen takes the port number from the environment variable LOGGINGPORT . If LOGGINGPORT is not set, lopen uses a default port number of 20100. The GUI uses the same default port number. If successful, lopen returns a pointer of type LFILE that is used by other logging functions. If unsuccessful, lopen returns NULL .

 int lclose(LFILE *mf); 

close the connection to the GUI. If successful, lclose returns 0. If unsuccessful, lclose returns “1. The lclose function is not thread-safe. Do not close the connection while other threads can send messages to the GUI. Making this function thread-safe would add considerable overhead to the logging functions and it was decided that thread safety was not necessary.

 int lsendtime(LFILE *mf); 

automatically send the local time with each message. The time is sent as two integer values giving the number of seconds since the Epoch and an additional number of microseconds. If successful, lsendtime returns 0. If unsuccessful, lsendtime returns “1. The design of lsendtime allows the GUI to optionally display the time that the message was sent rather than the time it was received. Call lsendtime before sending any messages to the GUI. When the GUI is set to display send times rather than receive times, messages sent before this call are displayed without a time. Displaying send times is useful when all messages are sent from the same host or from hosts with synchronized clocks. Otherwise, the receive times are more useful. The lsendtime function returns 0 if successful and “1 if unsuccessful. The lsendtime function is not thread-safe. Do not call lsendtime while other threads of the same process are concurrently logging.

 int lgenerator(LFILE *mf, char *gen); 

set the generator string to be gen . The generator string appears in the gen column of the GUI to identify the output. If successful, lgenerator returns 0. If unsuccessful, lgenerator returns “1. Failure can occur only if the gen string is longer than LFILE_GENLENGTH or if mutex locking fails in a threaded environment. The generator string follows a format specification. The gen parameter is a string that will be the new generator. The generator string specifies a format for the generator sent to the remote GUI. The first occurrence of %p in the generator string is replaced with the process ID of the process sending the message. In a threaded environment, the first occurrence of %t is also replaced by the thread ID. If LUSETHREAD is defined, compiling with NOTHREADID defined causes %t to be replaced by 0. The specified generator overrides the default generator that is equivalent to %p in a nonthreaded environment and to %p.%t in a threaded environment ( LUSETHREAD defined). The default generator can be restored by a call to lgenerator with a NULL value of the gen parameter.

 int lprintf(LFILE *mf, char *fmt, ...); int lprintfg(LFILE *mf, char *gen, char *fmt, ...); 

output a string to the logger. The lprintf and lprintfg functions are identical with one exception: the latter uses gen for the generator of this message only and the former uses the default generator. If successful, these functions return 0. If unsuccessful, these functions return “1. The syntax and parameters are similar to fprintf . The fmt parameter specifies a format string, and the remaining parameters are values to be included in the message. These functions allow one additional format specification, %t , which is replaced by the current time with a precision of milliseconds . If the message automatically includes the time (because of a previous call to lsendtime ), the same time is used for both.

D.2.2 Implementation details

The logging facility can be used in a threaded or nonthreaded environment. The additional code for threaded operation is included if the constant LUSETHREAD is defined. The program uses mutex locks for synchronization. When LUSETHREAD is defined, all the functions are thread-safe except for lclose and lsendtime . Making these thread-safe would require additional synchronization every time the LFILE structure is accessed, adding considerable overhead and serializing much of the program being logged. The intention is that lopen and lsendtime be called before the threads are created and that lclose be called only when all logging has been completed. Optionally, you can avoid lclose completely by allowing the process exit to close the connection. Compiling with LSENDTIME defined causes the sending of the time to be the default.

To allow for maximum concurrency, separate mutexes are used to protect calls to the ctime function, calls to the lgenerator function, and access to the nextID variable.

Each connection to the GUI has an associated pipe. A call to lopen reserves three file descriptors: one for the connection to the GUI and two for the pipe. A new process is created to transfer anything written to the pipe to the GUI. This is done with a forked process rather than a thread so that the facility can be used in a nonthreaded environment. Also, some thread-scheduling mechanisms might not give sufficient priority to this thread when it is used with other CPU-bound threads.

The maximum-size message (including the message header) that can be sent is given by PIPE_BUF . This choice allows all messages sent through one connection to be passed atomically to the GUI by having them go through a single pipe shared by processes or threads. Messages sent through different connections are sorted by the GUI. POSIX specifies that PIPE_BUF must be at least _POSIX_PIPE_BUF , which has the value of 512. Typical values of PIPE_BUF may be 10 times this value, but even the minimum is suitable for logging simple error or status information.