NDT-DEV email list created

Revision: 664
Author:   kumar.internet2
Date:     Fri Sep 30 21:38:03 2011
Log:      protocol validation logging functionality added newly. The -u  
command line option can be used to set a non-default protocol log. Small  
cosmetic changes to function headers
http://code.google.com/p/ndt/source/detail?r=664

Added:
 /branches/kkumar_code_organize/src/ndtptestconstants.c
 /branches/kkumar_code_organize/src/ndtptestconstants.h
 /branches/kkumar_code_organize/src/runningtest.c
 /branches/kkumar_code_organize/src/runningtest.h
Modified:
 /branches/kkumar_code_organize/src/Makefile.am
 /branches/kkumar_code_organize/src/analyze.c
 /branches/kkumar_code_organize/src/logging.c
 /branches/kkumar_code_organize/src/logging.h
 /branches/kkumar_code_organize/src/network.c
 /branches/kkumar_code_organize/src/protocol.h
 /branches/kkumar_code_organize/src/test_meta_srv.c
 /branches/kkumar_code_organize/src/test_sfw_srv.c
 /branches/kkumar_code_organize/src/testoptions.c
 /branches/kkumar_code_organize/src/web100srv.c

=======================================
--- /dev/null
+++ /branches/kkumar_code_organize/src/ndtptestconstants.c	Fri Sep 30  
21:38:03 2011
@@ -0,0 +1,103 @@
+/**
+ * This file is used to store constants related to the NDTP tests.
+ * It also defines functions to get  descriptive names for tests
+ * and such utility functionality.
+ *
+ *  Created on: Sep 29, 2011
+ *      Author: kkumar
+ */
+
+#include <string.h>
+#include "ndtptests.h"
+
+// The arrays below rely on the ordering of corresponding enum in the .h  
file.
+// test names
+static char *_teststatusdescarray[] = {
+               "not started",
+               "started",
+               "in progress",
+               "incomplete",
+               "complete"
+};
+
+// names of tests.
+static char *_testnamesarray[] = {
+               "None",
+               "Middlebox",
+               "SFW",
+               "C2S",
+               "S2C",
+               "Meta"
+};
+
+// names of test messages to log in descriptive names instead of numbers
+static char * _testmsgtypesarray[] = {
+  "COMM_FAILURE",
+  "SRV_QUEUE",
+  "MSG_LOGIN",
+  "TEST_PREPARE",
+  "TEST_START",
+ "TEST_MSG",
+ "TEST_FINALIZE",
+ "MSG_ERROR",
+ "MSG_RESULTS",
+ "MSG_LOGOUT",
+ "MSG_WAITING",
+};
+
+// names of protocol message transmission directions
+static char *_txdirectionsarray[] = {
+               "none",
+               "client_to_server",
+               "server_to_client"
+};
+
+/**
+ * Get descriptive string for test name
+ * @param testid Id of the test
+ * @param *snamearg  storage for test name description
+ * @return char*  Descriptive string for test name
+ * */
+char *get_testnamedesc(enum TEST_ID testid, char *snamearg) {
+       snamearg = _testnamesarray[testid];
+       printf ("--current test name = %s for %d\n", snamearg ,testid);
+       return snamearg;
+}
+
+/**
+ * Get descriptive string for test status
+ * @param teststatus Integer status of the test
+ * @param *sstatusarg storage for test status description
+ * @return char*  Descriptive string for test status
+ * */
+char *get_teststatusdesc(enum TEST_STATUS_INT teststatus, char  
*sstatusarg) {
+       sstatusarg =  _teststatusdescarray[teststatus];
+       printf ("--current test status = %s, for %d \n", sstatusarg, 
teststatus);
+       return sstatusarg;
+}
+
+/**
+ * Get descriptive string for test direction.
+ * Directions could be C->S or S->C, currently.
+ * @param testdirection Test direction
+ * @param *sdirnarg  storage for test direction
+ * @return char*  Descriptive string fr Test direction
+ * */
+char *get_testdirectiondesc(enum Tx_DIRECTION testdirection, char  
*sdirnarg) {
+       sdirnarg = _txdirectionsarray[testdirection];
+	printf ("--current test direction = %s , for %d\n", sdirnarg,  
testdirection);
+       return sdirnarg;
+}
+
+/**
+ * Get descriptive string for protocol message types.
+ *
+ * @param msgtype Test direction
+ * @param *smsgtypearg  storage for test direction
+ * @return char* Descriptive string for Message type
+ * */
+char *get_msgtypedesc(int msgtype, char *smsgtypearg) {
+       smsgtypearg = _testmsgtypesarray[msgtype];
+       printf ("--current test type = %s , for %d\n", smsgtypearg, msgtype);
+       return smsgtypearg;
+}
=======================================
--- /dev/null
+++ /branches/kkumar_code_organize/src/ndtptestconstants.h	Fri Sep 30  
21:38:03 2011
@@ -0,0 +1,36 @@
+/**
+ * This file defines the various test types and other constants that the  
NDT protocol currently supports/uses.
+ *
+ * */
+
+#ifndef _JS_NDTPTESTS_H
+#define _JS_NDTPTESTS_H
+
+#define TEST_NONE 0
+#define TEST_MID (1L << 0)
+#define TEST_C2S (1L << 1)
+#define TEST_S2C (1L << 2)
+#define TEST_SFW (1L << 3)
+#define TEST_STATUS (1L << 4)
+#define TEST_META (1L << 5)
+
+#define TEST_NAME_DESC_SIZE 10 // will hold "string "middlebox", which is  
the longest name
+#define TEST_STATUS_DESC_SIZE 15 // test status < 15 chars
+#define TEST_DIRN_DESC_SIZE 20 // direction is either client_to_server or  
server_to_client
+#define MSG_TYPE_DESC_SIZE 15 // max size for now derived  
from "TEST_FINALIZE"
+
+// status of tests. Used mainly to log a "textual" explanation using below  
array
+enum  TEST_STATUS_INT { TEST_NOT_STARTED, TEST_STARTED, TEST_INPROGRESS,  
TEST_INCOMPLETE, TEST_ENDED } teststatusint;
+
+// Test IDs
+enum TEST_ID{ NONE, MIDDLEBOX, SFW, C2S, S2C, META } testid;
+
+// Transmission direction
+enum Tx_DIRECTION { NO_DIR, C_S , S_C} txdirection;
+
+char *get_testnamedesc(enum TEST_ID testid, char *stestnamearg);
+char *get_teststatusdesc(enum TEST_STATUS_INT teststatus, char  
*steststatusarg);
+char *get_testdirectiondesc(enum Tx_DIRECTION testdirection, char  
*stestdirectionarg);
+char *get_msgtypedesc(int msgtypearg, char *smsgtypearg) ;
+
+#endif
=======================================
--- /dev/null
+++ /branches/kkumar_code_organize/src/runningtest.c	Fri Sep 30 21:38:03  
2011
@@ -0,0 +1,145 @@
+/**
+ * This file contains functions that help get/set the currently
+ * running test
+ *
+ *  Created on: Sep 28, 2011
+ *      Author: kkumar
+ */
+#include "ndtptestconstants.h"
+#include "runningtest.h"
+
+/**
+ * Return the id of the currently running test.
+ * @return integer id of the currently running test.
+ */
+
+static int currentTest = TEST_NONE;
+static enum Tx_DIRECTION currentDirection = NONE;
+static char *senddirnstr;
+static char *recvdirnstr;
+
+/**
+ * array defining possible events pertaining to process status
+ */
+static char *_procstatusarray[] = { "unknown", "process_started",
+               "process_ended" };
+
+/**
+ * Get ID of currently running test
+ * @return integer current running test Id
+ * */
+
+int getCurrentTest() {
+       return currentTest;
+}
+
+/** Set the id of the currently running test.
+ * @param testId Id of the currently running test
+ */
+
+void setCurrentTest(int testId) {
+       currentTest = testId;
+}
+
+/**
+ * Get the current direction of the test.
+ * @return integer direction corresponding to an enumerator
+ * */
+int getCurrentDirn() {
+       return currentDirection;
+}
+
+/** Set the id of the currently running test.
+ * Then determine the string descriptions for
+ * the test directions for the current process.
+ * For example, for server process,
+ * the current-test-direction = S->C (send direction)
+ * , and the other/reverse
+ * direction is C->S (i.e the receive direction)
+ * This method has to be invoked by every process
+ * that decides to have protocol logging.
+ * An example direction: client->server or vice
+ * versa.
+ * @param testId Id of the currently running test
+ */
+
+void setCurrentDirn(enum Tx_DIRECTION directionarg) {
+       currentDirection = directionarg;
+       char currenttestdirn[TEST_DIRN_DESC_SIZE];
+       char othertestdirn[TEST_DIRN_DESC_SIZE];
+       switch (currentDirection) {
+       case S_C:
+               senddirnstr = get_testdirectiondesc(currentDirection, 
currenttestdirn);
+               recvdirnstr = get_testdirectiondesc(C_S, othertestdirn);
+               break;
+       case C_S:
+               senddirnstr = get_testdirectiondesc(currentDirection, 
currenttestdirn);
+               recvdirnstr = get_testdirectiondesc(C_S, othertestdirn);
+               break;
+       case NO_DIR:
+       default:
+               senddirnstr = get_testdirectiondesc(NO_DIR, currenttestdirn);
+               recvdirnstr = get_testdirectiondesc(NO_DIR, othertestdirn);
+               ;
+               break;
+       }
+}
+
+/** Get a description of the currently running test
+ * @returns descriptive name for the currently running test
+ */
+char *get_currenttestdesc() {
+       enum TEST_ID currenttestId = NONE;
+       char currenttestdesc[TEST_NAME_DESC_SIZE];
+       switch (getCurrentTest()) {
+       case TEST_MID:
+               currenttestId = MIDDLEBOX;
+               break;
+       case TEST_C2S:
+               currenttestId = C2S;
+               break;
+       case TEST_S2C:
+               currenttestId = S2C;
+               break;
+       case TEST_SFW:
+               currenttestId = SFW;
+               break;
+       case TEST_META:
+               currenttestId = META;
+               break;
+       case TEST_NONE:
+       default:
+               currenttestId = NONE;
+               break;
+       }
+       return get_testnamedesc(currenttestId, currenttestdesc);
+}
+
+/**
+ * get the current (send) direction. For example,
+ *  if this is the server process, then local direction = S->C
+ *  @return char* descriptive text of the current local direction
+ *  */
+char *get_currentdirndesc() {
+       return senddirnstr;
+}
+
+/**
+ * get the current reverse(recv) direction. For example,
+ *  if this is the server process, then local direction = C->S
+ *  @return char* descriptive text of the current reverse direction
+ *  */
+char *get_otherdirndesc() {
+       return recvdirnstr;
+}
+
+/**
+ * get descriptive test for status of process
+ *  @return char* descriptive text of the process status
+ *  */
+char *get_procstatusdesc(enum PROCESS_STATUS_INT procstatusarg, char  
*sprocarg) {
+       sprocarg = _procstatusarray[procstatusarg];
+       printf("--current test name = %s for %d\n", sprocarg, procstatusarg);
+       return sprocarg;
+}
+
=======================================
--- /dev/null
+++ /branches/kkumar_code_organize/src/runningtest.h	Fri Sep 30 21:38:03  
2011
@@ -0,0 +1,25 @@
+/**
+ * runningtest.h
+ *
+ *  Created on: Sep 29, 2011
+ *      Author: kkumar
+ */
+
+#ifndef RUNNINGTEST_H_
+#define RUNNINGTEST_H_
+
+#define PROCESS_STATUS_DESC_SIZE 17 // suffice to hold status defined below
+// indicates the status of process like the web100srv or web100clt
+enum  PROCESS_STATUS_INT { UNKNOWN, PROCESS_STARTED, PROCESS_ENDED };
+
+int getCurrentTest();
+void setCurrentTest(int testId);
+char *get_currenttestdesc ();
+int getCurrentDirn();
+void setCurrentDirn(enum Tx_DIRECTION directionarg);
+int getCurrentDirn();
+char *get_currentdirndesc ();
+char *get_otherdirndesc ();
+char *get_procstatusdesc(enum PROCESS_STATUS_INT procstatusarg, char  
*sprocarg);
+
+#endif /* RUNNINGTEST_H_ */
=======================================
--- /branches/kkumar_code_organize/src/Makefile.am      Sun May  8 04:04:21 
2011
+++ /branches/kkumar_code_organize/src/Makefile.am      Fri Sep 30 21:38:03 
2011
@@ -33,7 +33,7 @@
 bin_PROGRAMS = web100clt
 endif

-web100clt_SOURCES = web100clt.c network.c usage.c logging.c utils.c  
protocol.c \
+web100clt_SOURCES = web100clt.c network.c usage.c logging.c utils.c  
protocol.c runningtest.c ndtptestconstants.c \
                     test_sfw_clt.c test_mid_clt.c test_c2s_clt.c  
test_s2c_clt.c test_meta_clt.c
 web100clt_LDADD = $(I2UTILLIBDEPS) -lpthread $(ZLIB)
 web100clt_CPPFLAGS ='-DBASEDIR="$(ndtdir)"'
@@ -43,27 +43,28 @@
 genplot_LDADD = $(NDTLIBS) $(I2UTILLIBDEPS)
 genplot_CPPFLAGS ='-DBASEDIR="$(ndtdir)"'

-analyze_SOURCES = analyze.c usage.c logging.c
+analyze_SOURCES = analyze.c usage.c logging.c runningtest.c  
ndtptestconstants.c
 analyze_LDADD = $(NDTLIBS) $(I2UTILLIBDEPS) $(ZLIB)
 analyze_CPPFLAGS ='-DBASEDIR="$(ndtdir)"'

-fakewww_SOURCES = fakewww.c troute.c troute6.c tr-tree.c tr-tree6.c  
network.c usage.c logging.c
+fakewww_SOURCES = fakewww.c troute.c troute6.c tr-tree.c tr-tree6.c  
network.c usage.c logging.c \
+        runningtest.c ndtptestconstants.c
 fakewww_LDADD = $(I2UTILLIBDEPS) $(ZLIB)
 fakewww_CPPFLAGS ='-DBASEDIR="$(ndtdir)"'

-web100srv_SOURCES = web100srv.c web100-util.c web100-pcap.c web100-admin.c  
\
-                    network.c usage.c utils.c mrange.c logging.c  
testoptions.c \
+web100srv_SOURCES = web100srv.c web100-util.c web100-pcap.c web100-admin.c  
runningtest.c \
+                    network.c usage.c utils.c mrange.c logging.c  
testoptions.c ndtptestconstants.c \
                     protocol.c test_sfw_srv.c test_meta_srv.c ndt_odbc.c
 web100srv_LDFLAGS = $(NDTLDFLAGS) $(I2UTILLDFLAGS)
 web100srv_LDADD = $(NDTLIBS) $(I2UTILLIBS) $(I2UTILLIBDEPS) -lpthread  
$(ZLIB)
 web100srv_CPPFLAGS ='-DBASEDIR="$(ndtdir)"'
 web100srv_DEPENDENCIES = $(I2UTILLIBDEPS)

-viewtrace_SOURCES = viewtrace.c usage.c logging.c utils.c
+viewtrace_SOURCES = viewtrace.c usage.c logging.c utils.c runningtest.c  
ndtptestconstants.c
 viewtrace_LDADD = $(NDTLIBS) $(I2UTILLIBDEPS) $(ZLIB)
 viewtrace_CPPFLAGS ='-DBASEDIR="$(ndtdir)"'

-tr_mkmap_SOURCES = tr-mkmap.c tr-tree.c tr-tree6.c usage.c logging.c
+tr_mkmap_SOURCES = tr-mkmap.c tr-tree.c tr-tree6.c usage.c logging.c  
runningtest.c ndtptestconstants.c
 tr_mkmap_LDADD = $(NDTLIBS) $(I2UTILLIBDEPS) $(ZLIB)
 tr_mkmap_CPPFLAGS ='-DBASEDIR="$(ndtdir)"'

@@ -84,4 +85,4 @@
        $(I2UTILLIBMAKE)

 EXTRA_DIST = clt_tests.h logging.h mrange.h network.h protocol.h  
testoptions.h test_sfw.h test_meta.h \
-             troute.h tr-tree.h usage.h utils.h varinfo.h web100-admin.h  
web100srv.h ndt_odbc.h
+             troute.h tr-tree.h usage.h utils.h varinfo.h web100-admin.h  
web100srv.h ndt_odbc.h runningtest.h ndtptestconstants.h
=======================================
--- /branches/kkumar_code_organize/src/analyze.c        Fri Sep 23 13:50:35 
2011
+++ /branches/kkumar_code_organize/src/analyze.c        Fri Sep 30 21:38:03 
2011
@@ -34,7 +34,7 @@
 #include "logging.h"

 #define LOGFILE "web100srv.log"
-#define PROTOLOGFILE "web100srvprotocol.log" //kk protocol validation
+#define PROTOLOGFILE "web100srvprotocol.log" /* protocol validation log */
 #define WEB100_VARS 128  /*number of web100 variables you want to access*/
 #define WEB100_FILE "web100_variables"  /*names of the variables to  
access*/
 #define BUFFSIZE 512
@@ -397,7 +397,7 @@

   iponly = 0;
   //while ((c = getopt_long(argc, argv, "dnhl:v", long_options, 0)) != -1)  
{
-  while ((c = getopt_long(argc, argv, "udnhl:v", long_options, 0)) != -1)  
{ //protocol validation, kk
+  while ((c = getopt_long(argc, argv, "udnhl:v", long_options, 0)) != -1) {
     switch (c) {
       case 'h':
         analyze_long_usage("ANL/Internet2 NDT version " VERSION "  
(analyze)");
@@ -409,11 +409,9 @@
       case 'l':
         LogFileName = optarg;
         break;
-      //kk for protocol validation
       case 'u':
-              ProtoLogFileName = optarg;
-              break;
-      //end protocol validation
+        ProtoLogFileName = optarg;
+        break;
       case 'n':
         iponly=1;
         break;
@@ -438,13 +436,11 @@
   }
   log_println(1, "log file = %s", LogFileName);

-  //protocol validation. kk new
   if (ProtoLogFileName == NULL) {
      sprintf(tmpstr, "%s/%s", BASEDIR, PROTOLOGFILE);
      ProtoLogFileName = tmpstr;
   }
   log_println(1, "log file = %s", ProtoLogFileName);
-  //end protocol validation

   if ((fp = fopen(LogFileName, "r")) == NULL)
     err_sys("Missing Log file ");
=======================================
--- /branches/kkumar_code_organize/src/logging.c        Fri Sep 23 13:50:35 
2011
+++ /branches/kkumar_code_organize/src/logging.c        Fri Sep 30 21:38:03 
2011
@@ -20,6 +20,10 @@
 /* #endif */

 #include "logging.h"
+//new addition after separating out ndtptests header, to include test types
+#include "testoptions.h" // Used only for getCurrentTest(), which can  
probably be moved elsewhere
+#include "runningtest.h" // protocol validation
+

 static int                _debuglevel        = 0;
 static char*              _programname       = "";
@@ -32,6 +36,8 @@
 static time_t             timestamp;
 static long int                  utimestamp;

+
+
 /**
  * Compress snaplog, tcpdump, and cputime files to save disk space.
  * These files compress by 2 to 3 orders of
@@ -192,26 +198,28 @@
 }

 /**
- * Function name: set_protologfile
- * Description: Sets the log filename.
- * Arguments: filename - new log filename
+ * set_protologfile
+ * Sets the protocol log filename.
+ * @param filename The new protocol log filename
  */
-
 void
 set_protologfile(char* filename)
 {
+       printf ("SET FILENAME=%s;", filename);
        ProtoLogFileName = filename;
+	printf ("END SET FILENAME=%s;", get_protologfile()); //protocol  
validation to remove printf
 }

 /**
- * Function name: get_protocollogfile
- * Description: Returns the protocol validation log filename.
- * Returns: The log filename
+ * Returns the protocol validation log filename.
+ * @returns The protocol log filename
  */

 char*
 get_protologfile()
 {
+  printf ("GET FILENAME=");
+  printf ("%s;\n",ProtoLogFileName);
   return ProtoLogFileName;
 }

@@ -296,10 +304,145 @@
   I2ErrLogVT(_errorhandler_nl,-1,0,format,ap);
   va_end(ap);
 }
+
+
+/** Log in a single key-value pair as a particular event
+ *
+ * In future, based on need, this may be expanded to log
+ * in a list of key-value pairs
+ *
+ */
+void
+protolog_printgeneric(int lvl,  const char* key, const char* value)
+{
+       FILE *fp;
+       //va_list   ap;
+
+       if (lvl > _debuglevel) {
+               return;
+       }
+
+       fp = fopen(get_protologfile(),"a");
+       if (fp == NULL) {
+		printf("--Unable to open proto file while trying to record  
key-vale: %s:%s \n", key, value);
+		log_println(0, "--Unable to open proto file while trying to record  
msg: %s \n", key, value);
+       }
+       else {
+               fprintf(fp, " event = \"%s\", name = \"%s\" \n", key, value);
+               printf("%s = \"%s\" \n", key, value);
+               fclose(fp);
+       }
+}

 /**
- * Function name: set_timestamp
- * Description: Sets the timestamp to actual time.
+ * Logs a protocol message specifically indicating the start/end or other  
status of tests
+ * @param lvl Level of the message
+ * @param testid enumerator indicating name of the test @see TEST_ID
+ * @param pid PID of process
+ * @param teststatus enumerator indicating test status. @see  
TEST_STATUS_INT
+ * TODO: It may be good to define constants for event, pid etc. Use these  
instead.
+ */
+void
+protolog_status(int lvl, int pid, enum  TEST_ID testid, enum  
TEST_STATUS_INT teststatus)
+{
+       FILE *fp;
+       va_list   ap;
+   char protomessage[256];
+   char currenttestarr[TEST_NAME_DESC_SIZE];
+   char currentstatusarr[TEST_STATUS_DESC_SIZE];
+   char *currenttestname = "";
+   char *teststatusdesc = "";
+
+   //get descriptive strings for test name and status
+   currenttestname = get_testnamedesc(testid, currenttestarr);
+   teststatusdesc = get_teststatusdesc(teststatus, currentstatusarr);
+
+       if (lvl > _debuglevel) {
+               return;
+       }
+
+       fp = fopen(get_protologfile(),"a");
+       if (fp == NULL) {
+		printf("--Unable to open protocol log file while trying to record test  
status message: %s for the %s test \n",
+                               teststatusdesc, currenttestname);
+		log_println(0, "--Unable to open protocol log file while trying to  
record test status message: %s for the %s test \n",
+                               teststatusdesc, currenttestname);
+       }
+       else {
+		sprintf(protomessage, " event = \"%s\", name=\"%s\", pid=\"%d\"  
\n",teststatusdesc, currenttestname, pid );
+		printf("%s: <-- %d - %s - %s --> \n ", protomessage, pid,  
teststatusdesc, currenttestname );
+               fprintf(fp, "%s", protomessage);
+               fclose(fp);
+       }
+}
+
+/** Log all send/receive protocol messages.
+ * @param lvl Level of the message
+ * @param *msgdirection Direction of msg (S->C, C->S)
+ * @param type message type
+ * @param *msg Actual message
+ * @param len Message length
+ * @param processid PID of process
+ * @param ctlSocket socket over which message has been exchanged
+ * */
+
+void protolog_println(int lvl, char *msgdirection,
+		 const int type, void* msg, const int len, const int processid, const  
int ctlSocket)
+{
+       FILE *fp;
+       char currentdrcnarr[TEST_DIRN_DESC_SIZE];
+       char msgtypedescarr[MSG_TYPE_DESC_SIZE];
+       char *currenttestname, *currentmsgtype;
+
+       // get descriptive strings for test name and direction
+       currenttestname = get_currenttestdesc();
+       currentmsgtype = get_msgtypedesc(type,msgtypedescarr);
+
+       fp = fopen(get_protologfile(),"a");
+        if (fp == NULL) {
+                 //printf("--Unable to open proto, RCV");
+		  log_println(0, "Unable to open protocol log file '%s\n', continuing on  
without logging", get_protologfile());
+        }
+        else {
+		  fprintf(fp, " event = \"message\", direction = \"%s\", test=\"%s\",  
type=\"%s\", len=\"%d\", msg=\"%s\", pid=\"%d\", socket=\"%d\"\n",
+				  msgdirection, currenttestname, currentmsgtype, len, (char*)msg,  
processid, ctlSocket);
+		  printf("direction = %s, test= %s, type=%s, len=%d, msg=%s, pid=%d,  
socket=%d\n",
+		 				  msgdirection, currenttestname, currentmsgtype, len, (char*)msg,  
processid, ctlSocket);
+                 fclose(fp);
+        }
+}
+
+/** Log "sent" protocol messages.
+ * Picks up the "send" direction and calls the generic protocol log method.
+ * @param lvl Level of the message
+ * @param type message type
+ * @param *msg Actual message
+ * @param len Message length
+ * @param processid PID of process
+ * @param ctlSocket socket over which message has been exchanged
+ * */
+void protolog_sendprintln (int lvl, const int type, void* msg, const int  
len, const int processid, const int ctlSocket) {
+         char *currentDir = get_currentdirndesc();
+         protolog_println(lvl, currentDir, type, msg, len, processid, 
ctlSocket);
+}
+
+/**
+ * Log all received protocol messages.
+ * Picks up the "receive" direction and calls the generic protocol log  
method.
+ * @param lvl Level of the message
+ * @param type message type
+ * @param *msg Actual message
+ * @param len Message length
+ * @param processid PID of process
+ * @param ctlSocket socket over which message has been exchanged
+ * */
+void protolog_rcvprintln  (int lvl, const int type, void* msg, const int  
len, const int processid, const int ctlSocket){
+        char *otherDir = get_otherdirndesc();
+         protolog_println(lvl, otherDir, type, msg, len, processid, 
ctlSocket);
+}
+
+/**
+ * Set the timestamp to actual time.
  */
 void
 set_timestamp()
=======================================
--- /branches/kkumar_code_organize/src/logging.h        Fri Sep 23 13:50:35 
2011
+++ /branches/kkumar_code_organize/src/logging.h        Fri Sep 30 21:38:03 
2011
@@ -13,6 +13,7 @@
 #include <dirent.h>
 #include <sys/stat.h>
 #include <sys/types.h>
+#include "ndtptestconstants.h"

 #define LOGFILE "web100srv.log"   /* Name of log file */
 #define PROTOLOGFILE "web100srvprotocol.log"   /* Name of protocol  
validation log file */
@@ -20,8 +21,10 @@
 void log_init(char* progname, int debuglvl);
 void set_debuglvl(int debuglvl);
 void set_logfile(char* filename);
+void set_protologfile(char* filename);
 int get_debuglvl();
 char* get_logfile();
+char* get_protologfile();
 I2ErrHandle get_errhandle();
 void log_print(int lvl, const char* format, ...);
 void log_println(int lvl, const char* format, ...);
@@ -37,6 +40,7 @@

 int zlib_def(char *src_fn);

+
 /**
  * Format used to exchange meta test data between client->server.
  * */
@@ -73,5 +77,13 @@
     struct metaentry* additional; // all other additional data
 };

+
+void protolog_printgeneric(int lvl, const char* key, const char* val);
+void protolog_status(int lvl, int pid, enum  TEST_ID testid, enum  
TEST_STATUS_INT teststatus);
+void protolog_println(int lvl, char *msgdirection,
+		 const int type, void* msg, const int len, const int processid, const  
int ctlSocket);
+void protolog_sendprintln (int lvl, const int type, void* msg, const int  
len, const int processid, const int ctlSocket);
+void protolog_rcvprintln  (int lvl, const int type, void* msg, const int  
len, const int processid, const int ctlSocket);
+
 struct metadata meta;
 #endif
=======================================
--- /branches/kkumar_code_organize/src/network.c        Fri Sep 23 13:50:35 
2011
+++ /branches/kkumar_code_organize/src/network.c        Fri Sep 30 21:38:03 
2011
@@ -425,16 +425,11 @@
   if (i == 5)
     return -3;
   log_println(8, ">>> send_msg: type=%d, len=%d, msg=%s, pid=%d", type,  
len, msg, getpid());
-  // kk start
-  fp = fopen(get_protologfile(),"a");
-  if (fp == NULL) {
-	  log_println(0, "Unable to open protocol log file '%s', continuing on  
without logging", get_logfile());
-  }
-  else {
-	  fprintf(fp, "Sent message: type=%d, len=%d, msg=%s, pid=%d on  
socket=%d\n", type, len, msg, getpid(), ctlSocket);
-         fclose(fp);
-  }
-  // kk end
+
+  //todo level = 0 could be made into a constant or option. move out of  
here in that case
+  protolog_sendprintln(0,
+                 type, msg, len, getpid(),ctlSocket);
+
   return 0;
 }

@@ -460,6 +455,14 @@
   int length;
   FILE *fp; //kk

+  // todo remove
+
+  int itype = *type;
+  int ilen = *len;
+  char *msgtemp = (char*)msg;
+
+  //end
+
   assert(type);
   assert(msg);
   assert(len);
@@ -485,18 +488,11 @@
     return -3;
   }
   log_println(8, "<<< recv_msg: type=%d, len=%d", *type, *len);
-  //kk here
-  fp = fopen(get_protologfile(),"a");
-  if (fp == NULL) {
-	  log_println(0, "Unable to open protocol log file '%s', continuing on  
without logging", get_logfile());
-  }
-  else {
-	  //fprintf(fp, "Rcd message: type=%d, len=%d, msg=%s, pid=%d on  
socket=%d\n", *type, *len, (char*)msg, getpid(), ctlSocket);
-	  fprintf(fp, "Rcd message: type=%d, len=%d,pid=%d on socket=%d\n",  
*type, *len, getpid(), ctlSocket);
-
-         fclose(fp);
-  }
-  //end kk
+
+  //todo level = 0 could be made into a constant or option. move out of  
here in that case
+  //protolog_rcvprintln(0, itype, msgtemp, ilen, getpid(),ctlSocket);
+  protolog_rcvprintln(0, *type, msgtemp, *len, getpid(),ctlSocket);
+
   return 0;
 }

=======================================
--- /branches/kkumar_code_organize/src/protocol.h       Sun May  8 04:04:21 
2011
+++ /branches/kkumar_code_organize/src/protocol.h       Fri Sep 30 21:38:03 
2011
@@ -9,6 +9,10 @@
 #ifndef _JS_PROTOCOL_H
 #define _JS_PROTOCOL_H

+//new addition after separating out ndtptests header
+#include "ndtptestconstants.h" //protocol validation
+
+// Todo could be made into enumeration
 #define COMM_FAILURE 0
 #define SRV_QUEUE 1
 #define MSG_LOGIN 2
@@ -21,6 +25,7 @@
 #define MSG_LOGOUT 9
 #define MSG_WAITING 10

+/*
 #define TEST_NONE 0
 #define TEST_MID (1L << 0)
 #define TEST_C2S (1L << 1)
@@ -28,6 +33,7 @@
 #define TEST_SFW (1L << 3)
 #define TEST_STATUS (1L << 4)
 #define TEST_META (1L << 5)
+*/

 #define TOPT_DISABLED 0
 #define TOPT_ENABLED 1
=======================================
--- /branches/kkumar_code_organize/src/test_meta_srv.c	Fri Sep 23 13:50:35  
2011
+++ /branches/kkumar_code_organize/src/test_meta_srv.c	Fri Sep 30 21:38:03  
2011
@@ -47,16 +47,25 @@
   struct metaentry *new_entry = NULL;
   char* value;

+  // protocol validation logs
+  enum TEST_ID testids = META;
+  enum TEST_STATUS_INT teststatuses = TEST_NOT_STARTED;
+
   if (testOptions->metaopt) {
     setCurrentTest(TEST_META);
     log_println(1, " <-- META test -->");

+    // log protocol validation details
+    teststatuses = TEST_STARTED;
+    protolog_status(0,testOptions->child0, testids, teststatuses);
+
     // first message exchanged is am empty TEST_PREPARE message
     j = send_msg(ctlsockfd, TEST_PREPARE, "", 0);
     if (j == -1 || j == -2) { // Cannot write message headers/data
        log_println(6, "META Error!, Test start message not sent!");
        return j;
     }
+

     // Now, transmit an empty TEST_START message
     if (send_msg(ctlsockfd, TEST_START, "", 0) < 0) {
@@ -136,7 +145,12 @@
          log_println(6, "META test - failed to send finalize message");
        }

+       //log end of test and conclude
     log_println(1, " <-------------------------->");
+
+    teststatuses = TEST_ENDED; // protocol log section
+    protolog_status(0,testOptions->child0, testids, teststatuses);
+
     setCurrentTest(TEST_NONE);
   }
   return 0;
=======================================
--- /branches/kkumar_code_organize/src/test_sfw_srv.c	Fri Sep 23 13:50:35  
2011
+++ /branches/kkumar_code_organize/src/test_sfw_srv.c	Fri Sep 30 21:38:03  
2011
@@ -48,7 +48,6 @@
  * In other words, sends the S->C TEST_MSG with message body
  * "Simple firewall test"
  * @param vptr void pointer
- * @todo protocol validation log at line 67
  */

 void*
@@ -84,12 +83,13 @@
  * Wait for the every thread to conclude and finalize
  *              the SFW test.
  * @param ctlsockfd Client control socket descriptor
- * @todo protocol validation log at line 97
  */

 void
 finalize_sfw(int ctlsockfd)
 {
+  enum TEST_ID thistestId = SFW;
+  enum TEST_STATUS_INT teststatusnow = NONE;
   // wait for mutex to be released before attempting to finalize
   while (toWait) {
     pthread_mutex_lock( &mainmutex);
@@ -97,9 +97,14 @@
     pthread_mutex_unlock( &mainmutex);
   }

-  // close the SFW test by sending a nil (0 length) message and set test  
status
+  // close the SFW test by sending a nil (0 length) message
   send_msg(ctlsockfd, TEST_FINALIZE, "", 0);
+
+  // log
+  teststatusnow = TEST_ENDED;
+  protolog_status(1, getpid() , thistestId, teststatusnow); //todo will  
getpid() be correct?
   log_println(1, " <-------------------------->");
+  // unset test name
   setCurrentTest(TEST_NONE);
 }

@@ -136,12 +141,19 @@
   char hostname[256];
   int rc;

+  // variables used for protocol validation
+  enum TEST_ID thistestId = NONE;
+  enum TEST_STATUS_INT teststatusnow = TEST_NOT_STARTED;
+
   assert(ctlsockfd != -1);
   assert(options);

   if (options->sfwopt) {
     setCurrentTest(TEST_SFW);
     log_println(1, " <-- %d - Simple firewall test -->", options->child0);
+    thistestId = SFW;
+    teststatusnow = TEST_STARTED;
+    protolog_status(1, options->child0, thistestId, teststatusnow);

     // bind to a new port and obtain address structure with details of  
port etc
     sfwsrv_addr = CreateListenSocket(NULL, "0", conn_options, 0);
@@ -241,6 +253,10 @@
     if ((sfwcli_addr = I2AddrByNode(get_errhandle(), hostname)) == NULL) {
       log_println(0, "Unable to resolve server address"); //todo is'nt  
this client address we cannot resolve?
       send_msg(ctlsockfd, TEST_FINALIZE, "", 0);
+
+      // log end
+      teststatusnow = TEST_ENDED;
+      protolog_status(0,options->child0, thistestId, teststatusnow);
       log_println(1, " <-------------------------->");
       I2AddrFree(sfwsrv_addr);
       return 5;
=======================================
--- /branches/kkumar_code_organize/src/testoptions.c	Fri Sep 23 13:50:35  
2011
+++ /branches/kkumar_code_organize/src/testoptions.c	Fri Sep 30 21:38:03  
2011
@@ -17,10 +17,11 @@
 #include "utils.h"
 #include "protocol.h"
 #include "I2util/util.h"
+#include "runningtest.h"

 int mon_pipe1[2];
 int mon_pipe2[2]; // used to store PIDs of pipes created for snap data in  
S2c test
-static int currentTest = TEST_NONE;
+//static int currentTest = TEST_NONE;

 typedef struct snapArgs {
   web100_snapshot* snap;
@@ -286,7 +287,11 @@
   char tmpstr[256];
   struct timeval sel_tv;
   fd_set rfd;
-
+
+  // variables used for protocol validation logging
+  enum TEST_ID thistestId = NONE;
+  enum TEST_STATUS_INT teststatusnow = TEST_NOT_STARTED;
+
   assert(ctlsockfd != -1);
   assert(agent);
   assert(options);
@@ -296,6 +301,12 @@
     setCurrentTest(TEST_MID);
     log_println(1, " <-- %d - Middlebox test -->", options->child0);

+    //protocol validation logs
+    printf(" <--- %d - Middlebox test --->", options->child0);
+    thistestId = MIDDLEBOX;
+    teststatusnow = TEST_STARTED;
+    protolog_status(1, options->child0, thistestId, teststatusnow);
+
     // determine port to be used. Compute based on options set earlier
     // by reading from config file, or use default port3 (3003),
     strcpy(listenmidport, PORT3);
@@ -343,7 +354,7 @@
     if (midsrv_addr == NULL) {
       log_println(0, "Server (Middlebox test): CreateListenSocket  
failed: %s", strerror(errno));
       sprintf(buff, "Server (Middlebox test): CreateListenSocket  
failed: %s", strerror(errno));
-      send_msg(ctlsockfd, MSG_ERROR, buff, strlen(buff)); //todo protocol  
validation log
+      send_msg(ctlsockfd, MSG_ERROR, buff, strlen(buff));
       return -1;
     }

@@ -354,7 +365,7 @@

     // send this port number to client
     sprintf(buff, "%d", options->midsockport);
-    if ((ret = send_msg(ctlsockfd, TEST_PREPARE, buff, strlen(buff))) < 0)  
//protocol validation log
+    if ((ret = send_msg(ctlsockfd, TEST_PREPARE, buff, strlen(buff))) < 0)
        return ret;

     /* set mss to 1456 (strange value), and large snd/rcv buffers
@@ -468,6 +479,13 @@
     close(options->midsockfd);
     send_msg(ctlsockfd, TEST_FINALIZE, "", 0);
     log_println(1, " <--------- %d ----------->", options->child0);
+
+    printf(" <--- %d - Middlebox test --->", options->child0);
+
+    // log end of test into protocol doc, just to delimit.
+    teststatusnow = TEST_ENDED;
+    protolog_status(1, options->child0, thistestId, teststatusnow);
+
     setCurrentTest(TEST_NONE);
   /* I2AddrFree(midsrv_addr); */
   }
@@ -530,11 +548,19 @@
   snapArgs.delay = options->snapDelay;
   wait_sig = 0;

+  // Test ID and status descriptors
+  enum TEST_ID testids = C2S;
+  enum TEST_STATUS_INT teststatuses = TEST_NOT_STARTED;
+
   if (testOptions->c2sopt) {
     setCurrentTest(TEST_C2S);
     log_println(1, " <-- %d - C2S throughput test -->",  
testOptions->child0);
     strcpy(listenc2sport, PORT2);

+    //log protocol validation logs
+    teststatuses = TEST_STARTED;
+    protolog_status(0,testOptions->child0, testids, teststatuses);
+
     // Determine port to be used. Compute based on options set earlier
     // by reading from config file, or use default port2 (3002).
     if (testOptions->c2ssockport) {
@@ -598,7 +624,7 @@
     log_println(1, "Sending 'GO' signal, to tell client %d to head for the  
next test", testOptions->child0);
     sprintf(buff, "%d", testOptions->c2ssockport);

-    // send TEST_PREPARE message with ephemreal port detail, indicating  
start of tests
+    // send TEST_PREPARE message with ephemeral port detail, indicating  
start of tests
     if ((ret = send_msg(ctlsockfd, TEST_PREPARE, buff, strlen(buff))) < 0)
        return ret;

@@ -778,7 +804,7 @@
     /* alarm(30); */  /* reset alarm() again, this 10 sec test should  
finish before this signal
                  * is generated.  */

-    // write into snaplog file, based on options. Lock/release resources  
as necessary
+    // write into snaplog file, based on options. Lock/release web10 log  
file as necessary
     {
         WorkerArgs workerArgs;
         workerArgs.snapArgs = &snapArgs;
@@ -920,7 +946,14 @@
       close(mon_pipe1[1]);
     }

+    // log end of C->S test
     log_println(1, " <----------- %d -------------->",  
testOptions->child0);
+    //protocol logs
+    teststatuses = TEST_ENDED;
+    protolog_status(0,testOptions->child0, testids, teststatuses);
+
+
+    //set current test status and free address
     setCurrentTest(TEST_NONE);
   /* I2AddrFree(c2ssrv_addr); */
   I2AddrFree(src_addr);
@@ -946,7 +979,7 @@
  *                             -2         - Cannot write message data while 
attempting to send
  *                      TEST_PREPARE message, or Unexpected message type 
received
  *             -3         -  Received message is invalid
- *          	-100   - timeout while waitinf for client to connect to  
serverÕs ephemeral port
+ *          	-100   - timeout while waiting for client to connect to  
serverÕs ephemeral port
  *                             -101   - Retries exceeded while waiting for 
client to connect
  *				-102   - Retries exceeded while waiting for data from connected  
client
  *                     -errno - Other specific socket error numbers
@@ -1004,11 +1037,20 @@
   snapArgs.delay = options->snapDelay;
   wait_sig = 0;

+  // variables used for protocol validation logs
+  enum TEST_STATUS_INT teststatuses = TEST_NOT_STARTED;
+  enum TEST_ID testids = S2C;
+
   // Determine port to be used. Compute based on options set earlier
   // by reading from config file, or use default port2 (3003)
   if (testOptions->s2copt) {
     setCurrentTest(TEST_S2C);
     log_println(1, " <-- %d - S2C throughput test -->",  
testOptions->child0);
+
+    //protocol logs
+    teststatuses = TEST_STARTED;
+    protolog_status(0,testOptions->child0, testids, teststatuses);
+
     strcpy(listens2cport, PORT4);

     if (testOptions->s2csockport) {
@@ -1491,7 +1533,12 @@
       close(mon_pipe2[1]);
     }

+    // log end of test (generic and protocol logs)
     log_println(1, " <------------ %d ------------->",  
testOptions->child0);
+    //log protocol validation logs
+    teststatuses = TEST_ENDED;
+    protolog_status(1,testOptions->child0, testids, teststatuses);
+
     setCurrentTest(TEST_NONE);
     /* I2AddrFree(s2csrv_addr); */
     I2AddrFree(src_addr);
@@ -1503,23 +1550,4 @@
   return 0;
 }

-/**
- * Return the id of the currently running test.
- * @return integer id of the currently running test.
- */
-
-int
-getCurrentTest()
-{
-  return currentTest;
-}
-
-/** Set the id of the currently running test.
- * @param testId Id of the currently running test
- */
-
-void
-setCurrentTest(int testId)
-{
-  currentTest = testId;
-}
+
=======================================
--- /branches/kkumar_code_organize/src/web100srv.c      Fri Sep 23 13:50:35 
2011
+++ /branches/kkumar_code_organize/src/web100srv.c      Fri Sep 30 21:38:03 
2011
@@ -81,6 +81,8 @@
 #include "web100-admin.h"
 #include "test_sfw.h"
 #include "ndt_odbc.h"
+#include "runningtest.h"
+

 static char lgfn[256];
 static char wvfn[256];
@@ -179,6 +181,7 @@
   {"file", 1, 0, 'f'},
   {"interface", 1, 0, 'i'},
   {"log", 1, 0, 'l'},
+  {"protocol_log", 1, 0, 'u'},
   {"port", 1, 0, 'p'},
   {"midport", 1, 0, 302},
   {"c2sport", 1, 0, 303},
@@ -601,9 +604,15 @@
     else if (strncasecmp(key, "log_file", 3) == 0) {
       sprintf(lgfn, "%s", val);
       set_logfile(lgfn);
+      sprintf(lgfn, "%s", val);
       continue;
     }
-
+    else if (strncasecmp(key, "protocol_log", 12) == 0) {
+         sprintf(lgfn, "%s", val);
+         printf("protocol_log: %s\n", val); //todo remove printf
+         set_protologfile(lgfn);
+         continue;
+    }
     else if (strncasecmp(key, "admin_file", 10) == 0) {
       sprintf(apfn, "%s", val);
       AdminFileName = apfn;
@@ -937,6 +946,10 @@
   FILE *fp;

   web100_connection* conn;
+  // protocol logging addition
+  // start with a clean slate of currently running test and direction
+  setCurrentTest(TEST_NONE);
+

   stime = time(0);
   log_println(4, "Child process %d started", getpid());
@@ -1470,6 +1483,12 @@
   int j;
   char *name;

+  // variables used for protocol validation logs
+  char startsrvmsg[256]; // used to log start of server process
+  char *srvstatusdesc;
+  enum PROCESS_STATUS_INT srvstatusenum = UNKNOWN;
+  char statustemparr[PROCESS_STATUS_DESC_SIZE]; // temp storage for  
process name
+
   options.limit = 0;
   options.snapDelay = 5;
   options.avoidSndBlockUp = 0;
@@ -1485,7 +1504,7 @@
   memset(&testopt, 0, sizeof(testopt));
   /* sigset_t newmask, oldmask; */

-#ifdef AF_INET6
+ #ifdef AF_INET6
 #define GETOPT_LONG_INET6(x) "46"x
 #else
 #define GETOPT_LONG_INET6(x) x
@@ -1499,7 +1518,8 @@

   opterr = 0;
   while ((c = getopt_long(argc, argv,
-           
GETOPT_LONG_INET6(GETOPT_LONG_EXP("adhmoqrstvzc:x:b:f:i:l:p:T:A:S:")),  
long_options, 0)) != -1) {
+         //  
GETOPT_LONG_INET6(GETOPT_LONG_EXP("adhmoqrstvzc:x:b:f:i:l:p:T:A:S:")),  
long_options, 0)) != -1) {
+		   
GETOPT_LONG_INET6(GETOPT_LONG_EXP("adhmoqrstvzc:x:b:f:i:l:u:p:T:A:S:")),  
long_options, 0)) != -1) {
     switch (c) {
       case 'c':
         ConfigFileName = optarg;
@@ -1526,10 +1546,15 @@
   LoadConfig(argv[0], &lbuf, &lbuf_max);
   debug = 0;

+  // set options for test direction
+  enum Tx_DIRECTION currentDirn = S_C;
+  setCurrentDirn(currentDirn);
+   // end protocol logging
+
   // Get server execution options
   while ((c = getopt_long(argc, argv,
          //  
GETOPT_LONG_INET6(GETOPT_LONG_EXP("adhmoqrstvzc:x:b:f:i:l:p:T:A:S:")),  
long_options, 0)) != -1) {
-		   
GETOPT_LONG_INET6(GETOPT_LONG_EXP("adhmoqrstvzc:x:b:f:i:l:u:p:T:A:S:")),  
long_options, 0)) != -1) { //kk changed for protocol validation
+		   
GETOPT_LONG_INET6(GETOPT_LONG_EXP("adhmoqrstvzc:x:b:f:i:l:u:p:T:A:S:")),  
long_options, 0)) != -1) {
     switch (c) {
       case '4':
         conn_options |= OPT_IPV4_ONLY;
@@ -1587,11 +1612,11 @@
         device = optarg;
         break;
       case 'l':
-        set_logfile(optarg);
+       set_logfile(optarg);
         break;
-      case 'u': //kk addedd case for protocol validation
-              set_protologfile(optarg);
-              break;
+      case 'u':
+       set_protologfile(optarg);
+        break;
       case 'o':
         old_mismatch = 1;
         break;
@@ -1807,7 +1832,7 @@

   ndtpid = getpid();
   tt = time(0);
-  log_println(6, "NDT server (v%s) proces [%d] started at %15.15s",  
VERSION, ndtpid, ctime(&tt)+4);
+  log_println(6, "NDT server (v%s) process [%d] started at %15.15s",  
VERSION, ndtpid, ctime(&tt)+4);
   fp = fopen(get_logfile(),"a");
   if (fp == NULL) {
     log_println(0, "Unable to open log file '%s', continuing on without  
logging", get_logfile());
@@ -1821,6 +1846,13 @@
     syslog(LOG_FACILITY|LOG_INFO, "Web100srv (ver %s) process started",
         VERSION);

+  // create protocol validation entry every time a process starts up
+  sprintf(startsrvmsg, "Web100srv (ver %s)",VERSION);
+  srvstatusenum = PROCESS_STARTED;
+  srvstatusdesc = get_procstatusdesc(srvstatusenum, statustemparr);
+  protolog_printgeneric(0, srvstatusdesc, startsrvmsg);
+
+
   // scan through the interface device list and get the names/speeds of  
each
   //  if.  The speed data can be used to cap the search for the bottleneck  
link
   //  capacity.  The intent is to reduce the impact of interrupt  
coalescing on