Logo Search packages:      
Sourcecode: lfc version File versions  Download package

logging.c

/*
 * $Id: logging.c,v 1.1 2005/03/31 13:13:00 baud Exp $
 */

/*
 * Copyright (C) 1993-1999 by CERN/IT/PDP/DM
 * All rights reserved
 */
#ifndef lint
static char sccsid[] = "@(#)$RCSfile: logging.c,v $ $Revision: 1.1 $ $Date: 2005/03/31 13:13:00 $ CERN/IT/PDP/DM Fabien Collin" ;
#endif /* not lint */

/* logging.c : A facility for logging client I/O primitives 
 The logging filename is defined by RFIO/CLIENTLOG in shift.conf 
 If this variable is not defined, no client logging is done 
 To dump a client log, use dump_log */

#include "Castor_limits.h"
#include <stdio.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/times.h>
#include <time.h>
#include <fcntl.h>
#include <unistd.h>
#include <malloc.h>
#include <syslog.h>
#include <sys/uio.h>
#include "logging.h"
#include <trace.h>

typedef struct {              /* One opened file */
  OPEN_BUFFER rec_open;
  char filename[CA_MAXPATHLEN+1];
  ERROR_BUFFER rec_error;
  RECORD_BUFFER rec_record;
  int record_table[MAX_RECORD_TABLE];
  OPERATION *rec_op;
  int cur_op;
  int last_op;
  time_t session_start_real_time;
  time_t session_end_real_time;
  clock_t session_start_user_time;
  clock_t session_start_sys_time;
  clock_t session_end_user_time;
  clock_t session_end_sys_time;
} OPENFILE;

#define UNUSED 99999

static int client_logging = FALSE ;    /* True if client logging is enabled */
static int lf;                /* File handle for logging file */
static int panic = FALSE;     /* Something wrong, stop logging */
static long incarnation_date; /* A unique number (48 bits) to identify an application */
static short incarnation_pid;
static int start = TRUE;      /* Code executed only once in an application */
static OPENFILE *file_table = NULL; /* The file table */
static int length_file_table = 0;   /* Its size */
static int *fd_table = NULL;        /* The fd table : fd_table[index in file table] = file fd */
                                    /* Same size as file_table */

char *getconfent();

void logging_panic(err)
     int err;
{
  panic = TRUE;

  switch(err)
    {
    case SYSLOG_OVERFLOW:
      syslog(LOG_ALERT, "rfio: client logging stopped : record table overflow");
      break;
    case SYSLOG_OPEN:
      syslog(LOG_ALERT, "rfio: client logging stopped : open error");
      break;
    case SYSLOG_WRONG_FD:
      syslog(LOG_ALERT, "rfio: client logging stopped : wrong fd");
      break;
    case SYSLOG_WRITE:
      syslog(LOG_ALERT, "rfio: client logging stopped : write error");
      break;
    case SYSLOG_CLOSE:
      syslog(LOG_ALERT, "rfio: client logging stopped : close error");
      break;
    case SYSLOG_MALLOC:
      syslog(LOG_ALERT, "rfio: client logging stopped : malloc error");
      break;
    }
}

/*
  Open and create (if necessary) the logging file
  See RFIO/CLIENTLOG variable in shift.conf
*/
static int open_logfile()
{
  int fd;
  static char *log_filename;
  INIT_TRACE("rfio");

  log_filename = getconfent("RFIO","CLIENTLOG",0);

  if ((fd = open(log_filename,O_WRONLY|O_APPEND|O_CREAT,0666)) == -1) {
      TRACE(1,"log","Can't open file %s",log_filename);
      END_TRACE() ;
      return(-1);
  }
  else {
      TRACE(1,"log", "file opened (fd=%d)",fd);
      fchmod(fd,0666);
      END_TRACE() ;
      return(fd);
  }
}

/* 
  Find a record size in a record table
  Returns -1 if size not found
  Returns the index of the record size if found
*/
static int find_size(rt,l,size)
     int size;
     int rt[],l;
{
  int i;

  if (l >= MAX_RECORD_TABLE)
    {
      logging_panic(SYSLOG_OVERFLOW);
      return(-1);
    }

  if (l == 0)
    return(-1);
  else
    {
      for (i=0;i<l;i++)
      if (rt[i] == size)
        return(i);
      return(-1);
    }
}

/*
  Insert a record size in a record table
*/
static int insert_size(rt,l,f,size)
     int size;
     int rt[],l,f;
{
  if (l >= MAX_RECORD_TABLE)
    {
      file_table[f].rec_error.num |= ERR_RECORD_FULL;
      return(-1);
    }
  else
    {
      file_table[f].record_table[l] = size;
      return(file_table[f].rec_record.length++);
    }
}

/* Find a file table index given its file descriptor */
static int find_fd(fd)
     int fd;
{
  int i;

  for (i=0;i<length_file_table;i++)
      if (fd_table[i] == fd)
      return(i);

  return(-1);
}

/* Client logging initialization : Executed only once in a client application */
void rfio_logst()
{
  client_logging = (getconfent("RFIO","CLIENTLOG",0) == NULL) ? FALSE : TRUE;

  if (client_logging)
    {
      /* Execute this only once */
      if (start)
      {
        /* Open client logging file */
        if ((lf = open_logfile()) == -1) {
          logging_panic(SYSLOG_OPEN);
        }

        /* Incarnation = same number for several open of the same application */
        incarnation_date = time(NULL);
        incarnation_pid = (short) getpid();
        start = FALSE;
      }
    }
}

/* Called when a file is closed */
void rfio_logcl(fd)
     int fd;
{
  struct iovec buf[8];
  int f = 0;
  short filelength;
  struct tms time_usage;

  if (client_logging) {
      if (!panic) {
      /* Find file index in file table */
      if ((f = find_fd(fd)) == -1) 
        logging_panic(SYSLOG_WRONG_FD);

      if (!panic) {
              /* The fd_table entry is now free */
              fd_table[f] = UNUSED;
      
            /* Compute different values related to execution time */
                    file_table[f].session_end_real_time = time(NULL);
                    times(&time_usage);
                file_table[f].session_end_user_time = time_usage.tms_utime;
                file_table[f].session_end_sys_time = time_usage.tms_stime;
      
                    file_table[f].rec_open.session_real_time = file_table[f].session_end_real_time - file_table[f].session_start_real_time;
                file_table[f].rec_open.session_user_time = file_table[f].session_end_user_time - file_table[f].session_start_user_time;
                file_table[f].rec_open.session_sys_time = file_table[f].session_end_sys_time - file_table[f].session_start_sys_time;
      
            /* Write atomically the logging information in the logging file */
      
              buf[0].iov_base = (caddr_t)&file_table[f].rec_open;
              buf[0].iov_len = sizeof(OPEN_BUFFER);
              
              filelength = strlen(file_table[f].filename) + 1;
              buf[1].iov_base = (caddr_t)&filelength;
              buf[1].iov_len = sizeof(filelength);
      
              buf[2].iov_base = (caddr_t)file_table[f].filename;
              buf[2].iov_len = filelength;
      
              buf[3].iov_base = (caddr_t)&file_table[f].rec_error;
              buf[3].iov_len = sizeof(ERROR_BUFFER);
              
              buf[4].iov_base = (caddr_t)&file_table[f].rec_record;
              buf[4].iov_len = sizeof(RECORD_BUFFER);
      
              buf[5].iov_base = (caddr_t)file_table[f].record_table;
              buf[5].iov_len = file_table[f].rec_record.length * sizeof(long);
              
              buf[6].iov_base = (caddr_t)&file_table[f].cur_op;
              buf[6].iov_len = sizeof(int);
              
              buf[7].iov_base = (caddr_t)file_table[f].rec_op;
              buf[7].iov_len = file_table[f].cur_op * sizeof(LSEEK_BUFFER);
              
              if (writev(lf,buf,8) == -1) {
                  perror("writev");
                  logging_panic(SYSLOG_WRITE); 
              }
      /*
       * We can't close the logging file as we don't know when to do it...
       * We rely on exit to close all non-closed files in the client application
       *
       *  if (close(lf) < 0)
       *  logging_panic(SYSLOG_CLOSE);
       *      
       *  if (!panic)  {
       *    free(fd_table);
       *    free(file_table);
       *  }
       */
      
     } /* if (!panic) */
   }  /* if (!panic) */
  }
}

/* Called when an open is done */
void rfio_logop(fd,path,machine,flags)
     int fd,flags;
     char *path;
     char *machine;
{
  long date;
  struct tms time_usage;

  if (client_logging)
    {
      if (!panic)
      {
        /* One file more */
        length_file_table++;
        
        /* Allocate a new file entry in the file table */
        if (!file_table)
          {
            file_table = (OPENFILE *) malloc(sizeof(OPENFILE));
            if (!file_table)
            logging_panic(SYSLOG_MALLOC);
          }
        else
          {
            file_table = (OPENFILE *) realloc(file_table,length_file_table * sizeof(OPENFILE));
            if (!file_table)
            logging_panic(SYSLOG_MALLOC);
          }
        
        if (!panic)
          {
            /* Allocate a new entry in the fd table */
            if (!fd_table)
            {
              fd_table = (int *) malloc(sizeof(int));
              if (!fd_table)
                logging_panic(SYSLOG_MALLOC);
            }
            else
            {
              fd_table = (int *) realloc(fd_table,length_file_table * sizeof(int));
              if (!fd_table)
                logging_panic(SYSLOG_MALLOC);
            }
          }
      }
      
      if (!panic)
      {
        int new = length_file_table - 1;
        struct stat buf_stat;
        
        /* Put fd in fd table */
        fd_table[new] = fd;

        file_table[new].rec_open.command = LOG_OPEN;
        file_table[new].rec_open.uid = getuid();
          
        if (machine == NULL)
          file_table[new].rec_open.local = TRUE;
        else
          file_table[new].rec_open.local = FALSE;

        strcpy(file_table[new].filename,path);

        file_table[new].rec_open.flags = flags;

        if (rfio_stat(path,&buf_stat) != -1)
          file_table[new].rec_open.size = buf_stat.st_size;
        else
          file_table[new].rec_open.size = -1;
        
        if (!file_table[new].rec_open.local) 
          {
            strncpy(file_table[new].rec_open.machine,machine,8);
            file_table[new].rec_open.machine[8]='\0' ;
          }
        else
          file_table[new].rec_open.machine[0] = '\0';
        
        file_table[new].session_start_real_time = file_table[new].rec_open.date = time(NULL);
        times(&time_usage);
        file_table[new].session_start_user_time = time_usage.tms_utime;
        file_table[new].session_start_sys_time = time_usage.tms_stime;
        
        file_table[new].rec_open.incarnation_date = incarnation_date;
        file_table[new].rec_open.incarnation_pid = incarnation_pid;

        
        file_table[new].rec_error.command = LOG_ERRORS;
        file_table[new].rec_error.num = 0;

        file_table[new].rec_record.command = LOG_RECORD;
        file_table[new].rec_record.length = 0;

        file_table[new].rec_op = NULL;
        file_table[new].cur_op = 0;
        file_table[new].last_op = 0;
        
      }
    }
}

#define EXTEND_OPERATION \
  if (!file_table[f].rec_op) \
    { \
      if ((file_table[f].rec_op = (OPERATION *) malloc(sizeof(OPERATION))) == NULL) \
      logging_panic(SYSLOG_MALLOC); \
    } \
  else \
    if ((file_table[f].rec_op = (OPERATION *) realloc(file_table[f].rec_op,(file_table[f].cur_op + 1) * sizeof(OPERATION))) == NULL) \
      logging_panic(SYSLOG_MALLOC)

/* Called when an lseek is done */
void rfio_logls(fd,offset,whence)
     off_t offset;
     int fd,whence;
{
  int f;

  if (client_logging)
    {
      if (!panic)
      if ((f = find_fd(fd)) == -1)
        logging_panic(SYSLOG_WRONG_FD);

      if (!panic)
      {
        EXTEND_OPERATION;
        if (!panic)
          {
            switch(whence)
            {
            case SEEK_SET:
              file_table[f].rec_op[file_table[f].cur_op].lseek.command = LOG_LSEEK_SET;
              break;
            case SEEK_CUR:
              file_table[f].rec_op[file_table[f].cur_op].lseek.command = LOG_LSEEK_CUR;
              break;
            case SEEK_END:
              file_table[f].rec_op[file_table[f].cur_op].lseek.command = LOG_LSEEK_END;
              break;
            }
            file_table[f].rec_op[file_table[f].cur_op].lseek.offset = offset;
            
            /* Last operation was a lseek */
            file_table[f].last_op = LOG_LSEEK_SET;
            
            file_table[f].cur_op++;
          }
      }
    }
}

/* Called when a read is done */
void rfio_logrd(fd,size)
     int fd,size;
{
  int record;
  int f;

  if (client_logging)
    {
      if (!panic)
      if ((f = find_fd(fd)) == -1)
        logging_panic(SYSLOG_WRONG_FD);
  
      if (!panic)
      {
        /* Find record size in record table */
        if ((record = find_size(file_table[f].record_table,file_table[f].rec_record.length,size)) == -1)
          record = insert_size(file_table[f].record_table,file_table[f].rec_record.length,f,size);
        
        /* Record table not full */
        if (record != -1)
          {
            if (file_table[f].last_op != LOG_READ)
            {
              /* Create a new READ operation */
              EXTEND_OPERATION; 
              if (!panic)
                {
                  file_table[f].rec_op[file_table[f].cur_op].read.command = LOG_READ;
                  file_table[f].rec_op[file_table[f].cur_op].read.count = 1;
                  file_table[f].rec_op[file_table[f].cur_op++].read.record = record;
                }
            }
            else
            {
              /* Last operation was a READ */
              if (file_table[f].rec_op[file_table[f].cur_op - 1].read.record == record)
                /* With the same record size */
                file_table[f].rec_op[file_table[f].cur_op - 1].read.count++;
              else
                {
                  /* With a different record size */
                  EXTEND_OPERATION;
                  if (!panic)
                  {
                    file_table[f].rec_op[file_table[f].cur_op].read.command = LOG_READ;
                    file_table[f].rec_op[file_table[f].cur_op].read.count = 1;
                    file_table[f].rec_op[file_table[f].cur_op++].read.record = record;
                  }
                }
            }
          }
        if (!panic)
          file_table[f].last_op = LOG_READ;
      }
    }
}

/* Called when a write is done */
void rfio_logwr(fd,size)
     int fd,size;
{
  int record;
  int f;

  if (client_logging)
    {
      if (!panic)
      if ((f = find_fd(fd)) == -1)
        logging_panic(SYSLOG_WRONG_FD);
      
      if (!panic)
      {
        /* Find record size in record table */
        if ((record = find_size(file_table[f].record_table,file_table[f].rec_record.length,size)) == -1)
          record = insert_size(file_table[f].record_table,file_table[f].rec_record.length,f,size);
        
        /* Record table not full */
        if (record != -1)
          {
            if (file_table[f].last_op != LOG_WRITE)
            {
              /* Create a new WRITE operation */
              EXTEND_OPERATION;
              if (!panic)
                {
                  file_table[f].rec_op[file_table[f].cur_op].write.command = LOG_WRITE;
                  file_table[f].rec_op[file_table[f].cur_op].write.count = 1;
                  file_table[f].rec_op[file_table[f].cur_op++].write.record = record;
                }
            }
            else
            {
              /* Last operation was a WRITE */
              if (file_table[f].rec_op[file_table[f].cur_op - 1].write.record == record)
                /* With the same record size */
                file_table[f].rec_op[file_table[f].cur_op - 1].write.count++;
              else
                {
                  /* With a different record size */
                  EXTEND_OPERATION;
                  if (!panic)
                  {
                    file_table[f].rec_op[file_table[f].cur_op].write.command = LOG_WRITE;
                    file_table[f].rec_op[file_table[f].cur_op].write.count = 1;
                    file_table[f].rec_op[file_table[f].cur_op++].write.record = record;
                  }
                }
            }
          }
        if (!panic)
          file_table[f].last_op = LOG_WRITE;
      }
    }
}




Generated by  Doxygen 1.6.0   Back to index