debug.c

Path MPICH-V for MPICH the MPI Implementation

/** @file debug.c implements methods to print debug messages during ch_v execution
 *
 *  Macros are not fitted for not GNUC compiler, disabling ALL debug messages !!!
 * (including error notifications !)
 */
#include <sys/types.h>
#include <sys/socket.h>
#include <netinet/in.h>
#include <arpa/inet.h>
#include <netdb.h>
#include <stdio.h>
#include <stdarg.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <errno.h>       
#include <sys/stat.h>
#include <fcntl.h>
#include <time.h>
#include "config.h"
#include "debug.h"
#include "vtypes.h"

#define UIDLEN 16
#define MTU 65536
#define MAX_PREINIT_LOGS 10

unsigned long long totmalloc = 0;

static int fd = -1;
static char *preinit_logs[MAX_PREINIT_LOGS] = {0, };
static int nbpreinit_log;
static char uid[UIDLEN];
static int use_color;

static char *WARNING = "W ";
static char *ERROR   = "E ";
static char *QUIT    = "Q ";
static char *QERROR  = "QE";
static char *EMPTY   = "";

static int nbignored, nbforced;
static char **ignored_tags;
static char **forced_tags;

static unsigned int msgid;
struct msg {
  int len;
  char uid_and_msg[0]; /* at most [UIDLEN+MTU] */
};

#define LOGD_PORT 9010
#define LOG_PATH  "/tmp/"
#ifndef SERVERMARKB
#define SERVERMARKB '@'
#endif
#ifndef SERVERMARKE
#define SERVERMARKE '@'
#endif
#ifndef FILEMARKB
#define FILEMARKB '%'
#endif
#ifndef FILEMARKE
#define FILEMARKE '%'
#endif
#define PLUS  '+'
#define MINUS '-'

static int _my_uwrite(int sock, char *buf, int size);
static char *plogd;

void PLOGD_HUNT(char *file, int line)
{
	fprintf(stderr, "pid %d -- %s:%d plogd = %s\n", getpid(), file, line, plogd?plogd:"(null)");
}

#ifdef DEBUG
#define MAX_MEMLINE 50
#define MAX_REMLINE 128
#define DEBUG_SIGNAL SIGQUIT

static char  membuffer[MAX_MEMLINE * MAX_REMLINE];
static char *memline[MAX_MEMLINE];
static int   mempos = -1;

static void write_msg(const char *lvl, char *msg);

static void remember(const char *line)
{
  if( mempos == -1 ) return;
  snprintf(memline[mempos], MAX_REMLINE, "%s", line);
  mempos = (mempos + 1) % MAX_MEMLINE;
}

static void on_debug_signal(int s)
{
  int i;
 
  if( mempos != -1 )
  {
    write_msg(NULL, "***** INSTANT REPLAY OF DEBUG *****");
    for( i = 0; i < MAX_MEMLINE; i++)
      if(memline[(i+mempos+1)%MAX_MEMLINE][0])
        write_msg(NULL, memline[(i+mempos)%MAX_MEMLINE]);
    write_msg(NULL, "***** BACK TO REAL TIME *****");
  }
  signal(DEBUG_SIGNAL, on_debug_signal);
}

static void setup_debug_signal(void) __attribute__((constructor));
static void setup_debug_signal(void)
{
  int i;
  for(i = 0; i < MAX_MEMLINE; i++)
     memline[i] = membuffer + i * MAX_REMLINE;
  mempos=0;
  signal(DEBUG_SIGNAL, on_debug_signal);  
}

static int abort_print(const char *header)
{
  int i;
  int in_force = 0, in_ignore = 0;

  /* NULL, QQ, EE and WW are always forced! */
  if( header == NULL    ||
      header == WARNING ||
      header == ERROR   ||
      header == QERROR  ||
      header == QUIT    ||
      header == EMPTY )
    return 0;
  
  for(i = 0; i < nbforced; i++)
    if(!strcmp(forced_tags[i], "@") || strstr(header, forced_tags[i]))
      {
	in_force = 1;
	break;
      }

  for(i = 0; i < nbignored; i++) 
    if(!strcmp(ignored_tags[i], "@") || strstr(header, ignored_tags[i]))
      {
	in_ignore = 1;
	break;
      }

  if(in_ignore)
    return 1;
  if(in_force)
    return 0;
  return 1;
}
#else
static int abort_print(char *header) { return 0; }
static void remember(char *line) { }
#endif

static void abortlist_init(char *initline)
{
  int j;
  char *p;

  nbignored = nbforced = 0;

  p = initline;

  for(p = initline; *p && (*p != PLUS) && (*p != MINUS); p++);
  while(*p)
  {
    switch (*p++)
    {
      case PLUS:
        nbforced++;
	for(j = 0; p[j] && (p[j] != PLUS) && (p[j] != MINUS); j++) ;
	forced_tags = (char**)realloc(forced_tags, nbforced*sizeof(char*));
	forced_tags[nbforced-1] = (char*)malloc(j+1);
	memcpy(forced_tags[nbforced-1], p, j);
	forced_tags[nbforced-1][j] = 0;
	p+=j;
        break;
      case MINUS:
        nbignored++;
        for(j = 0; p[j] && (p[j] != PLUS) && (p[j] != MINUS); j++) ;
        ignored_tags = (char**)realloc(ignored_tags, nbignored*sizeof(char*));
        ignored_tags[nbignored-1] = (char*)malloc(j+1);
        memcpy(ignored_tags[nbignored-1], p, j);
        ignored_tags[nbignored-1][j] = 0;
        p+=j;
        break;
    }
  }
}

static void set_default_uid(void) __attribute__((constructor));
static void set_default_uid(void)
{
  int j;
  snprintf(uid, UIDLEN, "%d", getpid());
  for(j = strlen(uid); j < UIDLEN-1; j++)
    uid[j] = ' ';
  uid[j] = 0;
}

static void trace_separator(int fd)
{
  char buffer[64];
  time_t now;

  sprintf(buffer, "****************\n");
  write(fd, buffer, strlen(buffer));
  time(&now);
  sprintf(buffer, "* %s", ctime(&now));
  write(fd, buffer, strlen(buffer));
  sprintf(buffer, "****************\n");
  write(fd, buffer, strlen(buffer));  
}

void initLog(char *_uid, char *_logd)
{
  char *p;
  struct sockaddr_in remote;
  int i, nbsend;
  unsigned int a,b,c,d;
  int port;
  struct msg *m;
  char *logd;
 
  if(plogd == NULL)
    {
       if(_logd == NULL)
	 {
	       fprintf(stderr, "in %d, %s:%d Second call of initLog: !(%s ^ %s)\n",
		       getpid(), __FILE__, __LINE__, plogd?plogd:"(null)", 
		       _logd?_logd:"(null)");
	       plogd = strdup("+@");
	       logd  = strdup("+@");
	       sleep(10);
	 }
       else
	 {
	    logd = strdup(_logd);
	    plogd = strdup(logd);
	 }
    }
  else 
    {
      if(_logd != NULL) 
	fprintf(stderr, "%s:%d Second call of initLog: !(%s ^ %s)\n",
		__FILE__, __LINE__, plogd?plogd:"(null)", _logd?_logd:"(null)");
      else 
	logd = strdup(plogd);
    }

  if(_uid == NULL) 
    snprintf(uid, UIDLEN, "%d", getpid());
  else 
    snprintf(uid, UIDLEN, "%s", _uid);

  if(fd != -1)
    {
      fprintf(stderr, "Nobody on earth want to call initLog twice. Believe me.\n");
      return;
    }

  if(logd[0] == SERVERMARKB)
    {
      /* read logd server adress */
      for(p = logd + 1; *p && (*p != SERVERMARKE); p++) ;
      if(*p)
	{
	  *p++ = 0;
	  if(sscanf(logd + 1, "%d.%d.%d.%d:%d", &a, &b, &c, &d, &port) != 5)
	    {
	      if(sscanf(logd + 1, "%d.%d.%d.%d", &a, &b, &c, &d) != 4)
		{
		  fprintf(stderr, "initLog: %s is not a valid logd server adress. Log sent to local stderr\n", logd + 1);
		  fd = -2;
		}
	      port = LOGD_PORT;
#ifdef HARDDEBUG
	      fprintf(stderr, "initLog: no port specified, using default port %d\n", LOGD_PORT);
#endif
	    }
	  /* filling addr struct with what has been parsed */
	  remote.sin_family = AF_INET;
	  remote.sin_port   = htons(port);
	  remote.sin_addr.s_addr = a + (b << 8) + (c << 16) + (d << 24);
#ifdef HARDDEBUG
	  fprintf(stderr, "initLog: logs are sent to server %s:%d\n", inet_ntoa(remote.sin_addr), ntohs(remote.sin_port));
#endif
	  /* connecting */
	  if((fd = socket(AF_INET, SOCK_STREAM, 0)) < 0) 
	    {
	      perror("initLog@socket");
	      fprintf(stderr, "Log sent to local stderr\n");
	      fd = -2;
	    }
	  else 
	    {
	      if(connect(fd, (struct sockaddr*)&remote, sizeof(remote)) < 0)
		{
		  fprintf(stderr, "%s:%d\n", inet_ntoa(remote.sin_addr), ntohs(remote.sin_port));
		  perror("initLog@connect");
		  fprintf(stderr, "Log sent to local stderr\n");
		  close(fd);
		  fd = -2;
		}        
	    }
	}
      else 
	{
	  /* malformed address */
	  fprintf(stderr, "%s is not a valid logd server string, Log sent to local stderr\n", logd);
	  p = logd;
	  fd = -2;
	}
    }
  else
    {
      if(logd[0] == FILEMARKB)
	{
	  /* read local log file name */
	  for(p = logd + 1; *p && (*p != FILEMARKE); p++) ;
	  if(*p)
	    {
	      char *fname; 
      
	      *p++ = 0;
	      fname = malloc(strlen(LOG_PATH) + strlen(uid) + strlen(logd + 1) + 1);
	      strcpy(fname, LOG_PATH);
	      strcat(fname, logd + 1);
	      strcat(fname, uid);

	      fd = open(fname, O_CREAT | O_APPEND | O_WRONLY, 0666);
	      if(fd < 0)
		{ 
		  perror("initlog@open");
		  fprintf(stderr, "%s could not be opened, log sent to local stderr\n", fname);
		  fd = -2;
		}
	      else
		{
		  if(dup2(fd, 2) < 0)
		    {
		      perror("initlog@dup2");
		      fprintf(stderr, "stderr could not be redirected to %s, log sent to local stderr\n", fname);
		    }
		  
		  trace_separator(fd);
		  
		  close(fd);
		  fd = -2;
		}
	      free(fname);
	    }
	}
      else
	{
	  /*  send to local stderr */
	  p = logd;
	  fd = -2;
	}
    }
  
  if( (fd == -2) ) 
    use_color = 1;
  
  /* repository for log is set, reading black and white tag list */
  abortlist_init(p);

  for(i = 0; i < nbpreinit_log; i++)
    {
      m = (struct msg*)malloc(sizeof(struct msg)+strlen(uid)+strlen(preinit_logs[i]));
      m->len = htonl(strlen(uid)+strlen(preinit_logs[i]));
      memcpy(m->uid_and_msg, uid, strlen(uid));
      memcpy(m->uid_and_msg+strlen(uid), preinit_logs[i], strlen(preinit_logs[i]));
      nbsend = _my_uwrite(fd, (void *)m, htonl(m->len)+sizeof(struct msg));
      if( nbsend < htonl(m->len)+sizeof(struct msg) )
	perror("initLog::write");
      free(preinit_logs[i]);
      free(m);
      preinit_logs[i] = NULL;
    }
  nbpreinit_log = 0;

}

void closeLog(void)
{
  if(fd >= 0) 
    close(fd);
  if(fd == -2) 
    close(fd);
  fd = -1;
}

static const char *cste_to_char(const char *lvl)
{
  if(lvl == 0)
	  return EMPTY;
  if(lvl == LVL_WARNING)
	  return WARNING;
  if(lvl == LVL_ERROR)
	  return ERROR;
  if(lvl == LVL_QUIT)
	  return QUIT;
  if(lvl == LVL_QERROR)
	  return QERROR;
  return lvl;
}

static int color(const char *lvl)
{
  if(lvl == NULL)    return 44;/* blue background */
  if(lvl == WARNING) return 32;/* GREEN foreground */
  if(lvl == ERROR)   return 35;/* MAGENTA foreground */
  if(lvl == QUIT)    return 36;/* CYAN foreground */
  if(lvl == QERROR)  return 31;/* RED foreground */
  return 0;                    /* normal */
}

/** blocking send on TCP socket */
static int _my_uwrite(int sock, char *buf, int size)
{
    int n, written = 0;

    while( written < size ) {
      n = write( sock, buf+written, size-written);
      if( n <= 0 ) {
	if( ( n < 0 ) && ((errno == EINTR) || (errno == EAGAIN))) continue;
	return n;
      }
      written += n;
    }
    return written;
}

/** write the message m of level lvl, output-dependantly
 * @param lvl : the level of debug
 * @param m : the message to write
 */
static void write_msg(const char *lvl, char *m)
{
  int totlen;

  if(lvl == NULL)
    remember(m);

  if(abort_print(lvl))
    return;

  if(fd == -2)
    {
      if(use_color)
	fprintf(stderr, "%s\n", m);
      else
	fprintf(stderr, "%s\n", m);
      fflush( stderr );
      return;
    }
  
  if( (fd == -1) && (nbpreinit_log < MAX_PREINIT_LOGS)  )
    preinit_logs[nbpreinit_log++] = strdup(m);
  else
    {
      totlen = strlen(m);
      memcpy(m-strlen(uid), uid, strlen(uid));
      *(int*)(m-strlen(uid)-sizeof(struct msg)) = htonl(totlen+strlen(uid));
      if( _my_uwrite(fd, m-strlen(uid)-sizeof(struct msg), totlen+strlen(uid) + sizeof(struct msg))
	  < totlen+strlen(uid)+sizeof(struct msg) )
	perror("logMessage::write");
    }
}

/** returns the real memory space where one output method may
 *  write the header, then the data
 * @param buffer : the address of the malloced space
 * @param IN/OUT space : hold the remaining size in buffer
 * @return the true pointer
 */
static char *output_offset(char *buffer, int *space)
{
  if( fd == -2 )
    return buffer;
  *space -= UIDLEN + sizeof(struct msg);
  return buffer + UIDLEN + sizeof(struct msg);
}

/** prints the readable header at the begining of the buffer
 * @param b : then buffer to print to
 * @param size : the maximum amount of bytes writeable
 * @param header : the header (level of debug)
 * @param fname : the file name
 * @param func : the function name
 * @param lineno : the line number
 */
static void output_format(char *b, int size, const char *header, const char *fname, const char *func, const int lineno)
{
  struct timeval tv;
  if( fd == -2 )
    {
      if( use_color )
	snprintf(b, size, "[%dm[%s]<%s %s %s():%5d> ", 
		 color(header), uid, cste_to_char(header), fname, func, lineno);
      else
	snprintf(b, size, "[%s]<%s %s %s():%5d> ",
		 uid, cste_to_char(header), fname, func, lineno);
    }
  else
    {
      gettimeofday(&tv,NULL);
      snprintf(b, size, "<%s %s %s():%5d (%08d) %ld.%ld> ", header, fname, func, lineno, msgid++, tv.tv_sec, tv.tv_usec);
    }
}

static int vprintw(const char *header, const char *fname, const char *func, const int lineno, const char *fmt, va_list ap)
{
  char _msg[MTU + sizeof(struct msg)], *msg;
  int size;

  size = MTU+sizeof(struct msg);
  memset(_msg, 0, size);
  msg = output_offset(_msg, &size);
  output_format(msg, size, header, fname, func, lineno);
  vsnprintf(msg+strlen(msg), size-strlen(msg), fmt, ap);
  write_msg(header, msg);
  return 0;
}

static int vprinte(const int err, const char *header, const char* fName, const char *func, const int lineno, const char* fmt, va_list args)
{
  char _msg[MTU + sizeof(struct msg)], *msg;
  int  size;

  size = MTU+sizeof(struct msg);
  memset(_msg, 0, size);
  msg = output_offset(_msg, &size);
  output_format(msg, size, header, fName, func, lineno);
  vsnprintf(msg+strlen(msg), size-strlen(msg), fmt, args);
  snprintf(msg+strlen(msg), size-strlen(msg), ": (%d) %s", err, strerror(err));
  write_msg(header, msg);
  return 0;
}

void __log_message(const char *lvl, const char *file, const char *func, const int lineno, const char *format, ...)
{
  va_list ap;

  lvl = cste_to_char(lvl);
  va_start(ap, format);
  vprintw(lvl, file, func, lineno, format, ap);
  va_end(ap);
}

void __log_error(const char *lvl, const char *file, const char *func, const int lineno, const char *format, ...)
{
  va_list ap;
  int err;

  err = errno;
  
  lvl = cste_to_char(lvl);
  va_start(ap, format);
  vprinte(err, lvl, file, func, lineno, format, ap);
  va_end(ap);
  errno = err;
}