/*
 * $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;
	}
    }
}