- Introduced a new trace facility

- Fixed performance problems in many protocol drivers.


SKIPPED:
	psi/julprot.c
	psi/phytron.c
	psi/pmacprot.c
	psi/polterwrite.c
	psi/spss7.c

ascon.i

@@ -88,7 +88,8 @@ struct Ascon {
  *    value should be 1
  *    when the state was AsconReading, a 1 indicates that a character was read
  *    and the character is stored in the lastChar field. A 0 indicates
- *    that no character was read.
+ *    that no character was read. And this 0 has to be given, otherwise AsconTask 
+ *    goes into an endless loop till timeout is hit!
  *
  *
  * In most cases a custom handler may be a wrapper around AsconBaseHandler

conman.c

@@ -114,7 +114,20 @@ static char *ConName(long ident)
   snprintf(name, sizeof(name), "CON%ld", ident);
   return name;
 }
+/*--------------------------------------------------------------------------*/
+char *ConID(SConnection *pCon)
+{
+	static char id[132];
+	char host[80];
 
+	if(ANETvalidHandle(pCon->sockHandle)){
+		ANETinfo(pCon->sockHandle, host, sizeof(host));
+		snprintf(id,sizeof(id),"%s:%2.2d", host, pCon->sockHandle);
+	} else {
+		snprintf(id,sizeof(id),"disconnected:%2.2ld", pCon->ident);
+	}
+	return id;
+}
 /*--------------------------------------------------------------------------*/
 static void FreeConnection(SConnection * pCon)
 {
@@ -576,6 +589,9 @@ int SCWrite(SConnection * self, char *pBuffer, int iOut)
   if (pBuffer == NULL) {
     return 0;
   }
+  if(!SCinMacro(self)){
+	  traceCommand(ConID(self),"out:%s", pBuffer);
+  }
   return self->write(self, pBuffer, iOut);
 }
 
@@ -1033,6 +1049,9 @@ int SCWriteUUencoded(SConnection * pCon, char *pName, void *pData,
     ANETwrite(pCon->sockHandle, pPtr, iLength);
   }
 
+  traceCommand(ConID(pCon),"out:UUData %s %d", pName, iLength);
+
+
 #ifdef UUDEB
   fd = fopen("uubuffer.uu", "w");
   fputs(pPtr, fd);
@@ -1133,6 +1152,8 @@ int SCWriteZipped(SConnection * self, char *pName, void *pData,
     SCWrite(self, "ERROR: out of memory in SCWriteZipped", eError);
     return 0;
   }
+  traceCommand(ConID(self),"out:SICSBIN ZIP %s %d", pName, compressedLength);
+
 
   /* now reset the deflater and do the same with writing data */
   compStream.zalloc = (alloc_func) NULL;
@@ -1411,6 +1432,7 @@ int SCInvoke(SConnection * self, SicsInterp * pInter, char *pCommand)
   }
   strlcpy(pCopy->deviceID, pBueffel, SCDEVIDLEN);
   /* SCAdvanceContext(self,pBueffel); */
+  traceCommand(ConID(self),"in:%s", pCommand);
   iRet = InterpExecute(pInter, pCopy, pCommand);
   /* SCPopContext(self); */
   SCDeleteConnection(pCopy);

counter.c

@@ -255,6 +255,7 @@ static int CheckCountStatus(void *pData, SConnection * pCon)
   self->badStatusCount = 0;     /* clear: we managed to read OK */
   if (self->iCallbackCounter > 20) {
     InvokeCallBack(self->pCall, MONITOR, &sMon);
+    tracePar(self->name,"control:%f", fControl);
     self->iCallbackCounter = 0;
   } else {
     self->iCallbackCounter++;
@@ -521,11 +522,13 @@ static int SetCounterModeImpl(pCounter self, CounterMode eNew)
     for (i = 0; i < self->iExponent; i++) {
       self->pDriv->fPreset /= 10.;
     }
+    tracePar(self->name,"mode:timer");
   }
   if (eNew == ePreset) {
     for (i = 0; i < self->iExponent; i++) {
       self->pDriv->fPreset *= 10.;
     }
+    tracePar(self->name,"mode:monitor");
   }
   self->pDriv->eMode = eNew;
   return 1;
@@ -578,6 +581,8 @@ static int SetCounterPresetImpl(pCounter self, float fVal)
     fVal = nintf(fVal);
   }
   self->pDriv->fPreset = fVal;
+  tracePar(self->name,"preset:%f", fVal);
+
   return 1;
 }
 /*------------------------------------------------------------------------*/

devexec.c

@@ -115,6 +115,7 @@ void DevexecLog(char *operation, char *device)
             (long) tv.tv_sec, (long) tv.tv_usec);
     fflush(devLog);
   }
+  traceDevice("devexec","%s:%s",device, operation);
 }
 
 /*======================== internal data structures =======================*/

devser.c

@@ -25,6 +25,7 @@ struct DevSer {
   double startTime; /* fields for statistics */
   double comCount;
   long nComCount;
+  int comMaxState;
   double comMax;
   long errorCount;
   int inError;
@@ -174,6 +175,9 @@ static void LogResponse(DevSer *self, int error)
 		self->inError = 0;
 	}
 	self->startTime = -1;
+	if(responseTime > self->comMax/2.){
+		self->comMaxState++;
+	}
 }
 static void StartAscon(DevSer *self)
 {
@@ -196,7 +200,7 @@ static void AsconLog(DevSer *self)
 	}
 }
 void DevStatistics(DevSer *devser, double *avg, double *max,
-		long *errCount, int *errState)
+		int *maxCount, long *errCount, int *errState)
 {
 	if(devser->nComCount > 0){
 		*avg = devser->comCount/devser->nComCount;
@@ -206,6 +210,7 @@ void DevStatistics(DevSer *devser, double *avg, double *max,
 	*max = devser->comMax;
 	*errCount = devser->errorCount;
 	*errState = devser->inError;
+    *maxCount  = devser->maxCount;
 }
 void DevAsconStatistics(DevSer *self, double *avg, \
 		double *max, int *maxState, int *longCount)

devser.h

@@ -167,10 +167,12 @@ char * DevList(DevSer * devser);
  * \param devser The device serializer
  * \param avg The average response time
  * \param max The maximum response time
+ * \param maxCount how often the communication took longer then max/2.
  * \param errCount The count of communication errors detected so far.
  * \param errFlag A flag if the device is in an error state or not
  */
 void DevStatistics(DevSer *devser, double *avg, double *max,
+		int *maxCount,
 		long *errCount, int *errFlag);
 /**
  * \brief Get Ascon invocation statistics. This can help to stop

exebuf.c

@@ -20,6 +20,8 @@
 #include "status.h"
 #include "commandlog.h"
 
+char *ConID(SConnection *pCon); /* in conman.c */
+
 /*-----------------------------------------------------------------------*/
 pExeBuf exeBufCreate(char *name)
 {
@@ -262,6 +264,7 @@ int exeBufProcess(pExeBuf self, SicsInterp * pSics,
       }
     }
 
+    traceCommand(ConID(pCon),"batch:%s", cmd);
     status = Tcl_Eval(pTcl, cmd);
     if (status != TCL_OK) {
       if (pCon->sicsError == 0) {

genbinprot.c

@@ -114,6 +114,7 @@ static int GenBinHandler(Ascon *a)
 		          a->state = AsconTimeout;
 		        }
 		      }
+		      return 0;
 		    }
 		}
 		break;

histmem.c

@@ -597,6 +597,7 @@ int HistConfigure(pHistMem self, SConnection * pCon, SicsInterp * pSics)
     SCWrite(pCon, "ERROR: failed to configure histogram memory", eError);
     return 0;
   }
+  tracePar(self->pDes->name,"initialized");
   return 1;
 }
 
@@ -861,6 +862,7 @@ int GetHistogramDirect(pHistMem self, SConnection * pCon,
     iRet = self->pDriv->GetHistogram(self->pDriv, pCon,
                                      i, iStart, iEnd, lData);
     if (iRet == OKOK) {
+      tracePar(self->pDes->name,"!!datachange!!");
       break;
     } else {
       iRet = self->pDriv->GetError(self->pDriv, &iErr, pError, 79);

hmdata.c

@@ -299,6 +299,7 @@ static int updateHMbuffer(pHistMem hist, int bank, SConnection * pCon)
                                        self->localBuffer);
     if (status == OKOK) {
       self->nextUpdate = time(NULL) + self->updateIntervall;
+      tracePar(hist->pDes->name,"!!datachange!!");
       break;
     } else {
       status = hist->pDriv->GetError(hist->pDriv, &iErr, pError, 79);

make_gen

@@ -41,7 +41,7 @@ SOBJ =  network.o ifile.o conman.o SCinter.o splitter.o passwd.o \
        sgclib.o sgfind.o sgio.o sgsi.o sghkl.o singlediff.o singlebi.o \
        singlenb.o simindex.o simidx.o uselect.o singletas.o motorsec.o \
        rwpuffer.o asynnet.o background.o countersec.o hdbtable.o velosec.o \
-       histmemsec.o sansbc.o sicsutil.o strlutil.o genbinprot.o
+       histmemsec.o sansbc.o sicsutil.o strlutil.o genbinprot.o trace.o
  
 MOTOROBJ = motor.o  simdriv.o  
 COUNTEROBJ =  countdriv.o simcter.o counter.o

motor.c

@@ -362,6 +362,7 @@ static void finishDriving(pMotor self, SConnection * pCon)
   self->fPosition = sCall.fVal;
   InvokeCallBack(self->pCall, MOTDRIVE, &sCall);        /* send also very last position */
   InvokeCallBack(self->pCall, MOTEND, &sCall);
+  tracePar(self->name,"%f",sCall.fVal);
 }
 
 /*--------------------------------------------------------------------*/
@@ -468,6 +469,7 @@ static void handleMoveCallback(pMotor self, SConnection * pCon)
     MotorGetSoftPosition(self, pCon, &sCall.fVal);
     sCall.pName = self->name;
     InvokeCallBack(self->pCall, MOTDRIVE, &sCall);
+    tracePar(self->name,"%f",sCall.fVal);
     self->posCount = 0;
   }
 }
@@ -572,7 +574,9 @@ static int MotorSetParImpl(pMotor self, SConnection * pCon, char *name,
     if (iRet == 1) {
       SCparChange(pCon);
       InvokeCallBack(self->pCall, HDBVAL, self);
+      tracePar(self->name,"%s:%f",name, fVal);
       return iRet;
+
     }
   }
 
@@ -596,6 +600,7 @@ static int MotorSetParImpl(pMotor self, SConnection * pCon, char *name,
     ObParSet(self->ParArray, self->name, "softlowerlim", fLimit, pCon);
     SCparChange(pCon);
     InvokeCallBack(self->pCall, HDBVAL, self);
+    tracePar(self->name,"%s:%f",name, fVal);
 
     return 1;
   }
@@ -616,6 +621,7 @@ static int MotorSetParImpl(pMotor self, SConnection * pCon, char *name,
   }
   InvokeCallBack(self->pCall, HDBVAL, self);
   SCparChange(pCon);
+  tracePar(self->name,"%s:%f",name, fVal);
 
   return iRet;
 }

motorsec.c

@@ -309,14 +309,10 @@ static int SecMotorStatus(void *sulf, SConnection * pCon)
     if (SCGetInterrupt(pCon) < (int) interrupt) {
       SCSetInterrupt(pCon, (int) interrupt);
     }
-    if(self->stopped == 0) {
-      self->errorCount++;
-    }
     break;
   case HWIdle:
     self->posCount = 10000;
     handleMoveCallback(self, pCon);
-    self->errorCount = 0;
     break;
   }
   return status;
@@ -355,6 +351,10 @@ static int SecMotorHalt(void *sulf)
   haltFunc = (SICSOBJFunc) node->value.v.func;
   assert(haltFunc != NULL);
   self->stopped = 1;
+  self->pDrivInt->iErrorCount--;
+  if(self->pDrivInt->iErrorCount < 0){
+	  self->pDrivInt->iErrorCount = 0;
+  }
   return haltFunc((pSICSOBJ) self, pServ->dummyCon, node, par, 0);
 }
 
@@ -462,7 +462,7 @@ static hdbCallbackReturn SecMotorCallback(pHdb node, void *userData,
      * check for alarm condition
      */
     SecMotorGetPar(self, "failafter", &fVal);
-    if (self->errorCount > (int) fVal) {
+    if (self->pDrivInt->iErrorCount > (int) fVal) {
       /* big alarm */
       ServerWriteGlobal("ERROR: !!! MOTOR ALARM !!! MOTOR ALARM !!!",
                         eError);
@@ -471,7 +471,7 @@ static hdbCallbackReturn SecMotorCallback(pHdb node, void *userData,
               self->name);
       ServerWriteGlobal(pBueffel, eError);
       SCSetInterrupt(pCon, eAbortBatch);
-      self->errorCount = 0;
+      self->pDrivInt->iErrorCount = 0;
       return hdbAbort;
     }
 
@@ -553,10 +553,10 @@ static hdbCallbackReturn SecMotorSignCallback(pHdb node, void *userData,
     }
     SecMotorGetPar(self, "softlowerlim", &limit);
     limit *= v.v.doubleValue;
-    SecMotorSetPar(self, pCon, "softlowerlim", limit);
+    SecMotorSetPar(self, pCon, "softupperlim", limit);
     SecMotorGetPar(self, "softupperlim", &limit);
     limit *= v.v.doubleValue;
-    SecMotorSetPar(self, pCon, "softupperlim", limit);
+    SecMotorSetPar(self, pCon, "softlowerlim", limit);
     SecMotorSetPar(self, pCon, "softzero", .0);
     UpdateHipadabaPar(node, v, pCon);
     return hdbContinue;

nread.c

@@ -41,6 +41,7 @@
 #include "nread.h"
 #include "commandlog.h"
 #include "uselect.h"
+#include "trace.h"
 
 extern pServer pServ;
 extern int VerifyChannel(mkChannel * self);     /* defined in network.c */
@@ -62,6 +63,7 @@ typedef enum {
   tSE
 } TelnetStatus;
 
+extern char *ConID(SConnection *pCon); /* from conman.c */
 /*--------------------------------------------------------------------------*/
 typedef struct __netreader {
   pServer pMain;                /* The server ds */
@@ -260,6 +262,7 @@ static int NetReadRead(pNetRead self, pNetItem pItem)
   if (pPtr) {
     sscanf(pPtr, "%s %d", pMuell, &iInt);
     if (SCMatchRights(pItem->pCon, usUser)) {
+      traceCommand(ConID(pItem->pCon),"interrupt: %d",iInt);
       TaskSignal(self->pMain->pTasker, SICSINT, &iInt);
       snprintf(pBueffel,sizeof(pBueffel)-1, "INTERRUPT %d issued on sock %d",
               iInt, pItem->pCon->pSock->sockid);
@@ -451,6 +454,7 @@ static int TelnetRead(pNetRead self, pNetItem pItem)
         }
       }
       TaskSignal(self->pMain->pTasker, SICSINT, &iInt);
+      traceCommand(ConID(pItem->pCon),"interrupt: %d",iInt);
       snprintf(pError,sizeof(pError)-1, "INTERRUPT %d issued on sock %d", iInt,
               pItem->pCon->pSock->sockid);
       WriteToCommandLog("SYS>", pError);
@@ -1015,6 +1019,7 @@ static int testAndInvokeInterrupt(pCommandCBData self, int handle)
   if ((pInt = strstr(pPtr, "INT1712")) != NULL) {
     sscanf(pInt, "%s %d", buffer, &iInt);
     if (SCMatchRights(self->pCon, usUser)) {
+      traceCommand(ConID(self->pCon),"interrupt:%d",iInt);
       TaskSignal(pServ->pTasker, SICSINT, &iInt);
       snprintf(buffer, 512, "INTERRUPT %d issued on sock %d",
                iInt, handle);
@@ -1316,6 +1321,7 @@ static int TelnetAcceptCB(int handle, void *userData)
 /*------------------------------------------------------------------------------------*/
 static void NREADlog(int level, char *txt, void *userData)
 {
+  traceSys("anet",txt);
   puts(txt);
 }
 

nserver.c

@@ -252,6 +252,10 @@ int InitServer(char *file, pServer * pServ)
   AddCommand(self->pSics, "Performance", PerfMonWrapper, DeletePerfMon,
              pMon);
   TaskRegister(self->pTasker, PerfMonTask, PerfMonSignal, NULL, pMon, 1);
+  /* Install a second one for higher granularity measurement */
+  pMon = CreatePerfMon(2);
+  TaskRegister(self->pTasker, PerfMonTask, PerfMonSignal, DeletePerfMon, pMon, 1);
+
 
   /* install telnet port */
   InstallTelnet();

ofac.c

@@ -41,6 +41,7 @@ static void InitGeneral(void)
   INIT(HelpInit);
   INIT(AddTestProt);
   INIT(AddGenBinProtocoll);
+  INIT(MakeTrace);
   INIT(SiteInit);               /* site specific initializations */
 }
 
@@ -108,6 +109,7 @@ static void InitIniCommands(SicsInterp * pInter)
   PCMD("TclReplaceDrivable",    TclReplaceDrivable);
   PCMD("transact",              TransactAction);
   PCMD("wait",                  UserWait);
+  PCMD("checksum",              CheckSum);
 
   /* startup commands in alphabetic order */
   SCMD("allowexec",             AllowExec);

perfmon.c

@@ -130,6 +130,7 @@ int IncrementPerfMon(pPerfMon self)
       SICSLogWrite(pBueffel, eValue);
     }
     InvokeCallBack(self->pCall, VALUECHANGE, &self->fCPS);
+    traceSys("perfmon","%d:%f", self->iInteg, self->fCPS);
   }
   return 1;
 }

rs232controller.c

@@ -20,7 +20,12 @@
 #include "nread.h"
 #include "rs232controller.h"
 
-
+/*--------------------------------------------------------------------*/
+static char *MakeID(prs232 self){
+	static char id[132];
+	snprintf(id,sizeof(id),"%s:%d",self->pHost, self->iPort);
+	return id;
+}
 /*--------------------------------------------------------------------*/
 void setRS232SendTerminator(prs232 self, char *term)
 {
@@ -119,6 +124,11 @@ int writeRS232(prs232 self, void *data, int dataLen)
     }
     fflush(stdout);
   }
+  if(strlen((char *)data) <= dataLen){
+	  traceIO(MakeID(self),"out:%s",(char *)data);
+  } else {
+	  traceIO(MakeID(self),"out:%s","Binary output");
+  }
 
   if (pPtr != NULL)
     free(pPtr);
@@ -167,6 +177,11 @@ int readRS232(prs232 self, void *data, int *dataLen)
         }
         fflush(stdout);
       }
+      if(strlen((char *)data) <= *dataLen){
+          traceIO(MakeID(self),"in:%s",(char *)data);
+      } else {
+          traceIO(MakeID(self),"in:%s","Binary Input");
+      }
       *dataLen = lRead;
       return 1;
     } else {
@@ -208,11 +223,14 @@ int readRS232TillTerm(prs232 self, void *data, int *datalen)
     if (self->debug > 0) {
       printf("RS232 IN/TERM : TIMEOUT:%s\n", (char *) data);
     }
+    traceIO(MakeID(self),"in:%s","TIMEOUT");
     return TIMEOUT;
   } else if (iRet == -1) {
-    printf("Incomplete read: %s, errno = %d\n", (char *) data, errno);
+	  traceIO(MakeID(self),"in:%s %s","Incomplete read", (char *)data);
+	  printf("Incomplete read: %s, errno = %d\n", (char *) data, errno);
     return INCOMPLETE;
   } else if (iRet < 0) {
+	traceIO(MakeID(self),"in:Error %d",errno);
     return iRet;
   }
   if (*self->replyTerminator != 0) {
@@ -220,6 +238,7 @@ int readRS232TillTerm(prs232 self, void *data, int *datalen)
   } else {
     *datalen = iRet;
   }
+  traceIO(MakeID(self),"in:%s",(char *)data);
   return 1;
 }
 
@@ -343,11 +362,14 @@ int transactRS232(prs232 self, void *send, int sendLen,
     }
   }
   if (iRet == 0) {
+	traceIO(MakeID(self),"in:%s", "TIMEOUT");
     return TIMEOUT;
   } else if (iRet == -1) {
+		traceIO(MakeID(self),"in:%s:%d", "Incomplete read", errno);
     return INCOMPLETE;
   } else {
-    return iRet;
+	  traceIO(MakeID(self),"in:%s", (char *)reply);
+	  return iRet;
   }
 }
 
@@ -439,6 +461,8 @@ int initRS232WithFlags(prs232 self, int flags)
 
   assert(self);
 
+  traceIO(MakeID(self),"connect");
+
   if (self->pSock != NULL) {
     if (pServ->pReader != NULL) {
       NetReadRemoveUserSocket(pServ->pReader, self->pSock->sockid);

scriptcontext.c

@@ -35,6 +35,7 @@ struct SctController {
   Hdb *node;                    /* the controller node */
   SConnection *conn;
   int verbose;
+  FILE *fd;
 };
 
 /* action data and write callback data */
@@ -284,6 +285,9 @@ int SctCallInContext(SConnection * con, char *script, Hdb * node,
   if (verbose) {
     SCPrintf(con, eLog, "%6.3f script: %s", secondsOfMinute(), script);
   }
+  if (controller->fd != NULL) {
+    fprintf(controller->fd,"%6.3f script: %s\n", secondsOfMinute(), script);
+  }
 
   MacroPush(con);
   l = strlen(script);
@@ -298,7 +302,10 @@ int SctCallInContext(SConnection * con, char *script, Hdb * node,
       }
     }
     if (verbose) {
-      SCPrintf(con, eLog, "%6.3f error: %s", secondsOfMinute(), result);
+        SCPrintf(con, eLog, "%6.3f error: %s", secondsOfMinute(), result);
+    }
+    if(controller->fd != NULL){
+        fprintf(controller->fd, "%6.3f error: %s\n", secondsOfMinute(), result);
     }
     iRet = 0;
   }
@@ -365,10 +372,17 @@ static char *SctActionHandler(void *actionData, char *lastReply,
   script = NULL;
   if (!commError && controller->verbose && lastReply != NULL
       && *lastReply != '\0') {
-    SCPrintf(con, eLog, "%6.3f reply : %s\n", secondsOfMinute(), lastReply);
+	    SCPrintf(con, eLog, "%6.3f reply : %s\n", secondsOfMinute(), lastReply);
-    /**
+  }
-     * TODO: This is the end place of any communication for statistics measurement
+  if(!commError && controller->fd != NULL && lastReply != NULL && *lastReply != '\0'){
-     */
+	    fprintf(controller->fd, "%6.3f reply : %s\n", secondsOfMinute(), lastReply);
+  }
+  if(lastReply != NULL && *lastReply != '\0'){
+	   if(data != NULL && data->controller != NULL){
+		    traceIO(data->controller->node->name, "reply:%s", lastReply);
+	   } else {
+		    traceIO("sctunknown", "reply:%s", lastReply);
+	   }
   }
   
   /*
@@ -511,9 +525,14 @@ static char *SctActionHandler(void *actionData, char *lastReply,
       if (controller->verbose) {
         SCPrintf(con, eLog, "%6.3f send  : %s", secondsOfMinute(), send);
       }
-      /**
+      if (controller->fd != NULL) {
-       * TODO: this is another point where to introduce statistics, this is the start
+        fprintf(controller->fd, "%6.3f send  : %s\n", secondsOfMinute(), send);
-       */
+      }
+      if(data != NULL && data->controller != NULL){
+    	  traceIO(data->controller->node->name, "send:%s", send);
+      } else {
+    	  traceIO("sctunknown", "send:%s", send);
+      }
       return send;
     }
   }
@@ -1115,13 +1134,29 @@ static char *TransactionHandler(void *actionData, char *lastReply,
     if (st->controller->verbose) {
       SCPrintf(st->con, eLog, "%6.3f send  : %s", secondsOfMinute(), st->command);
     }
+    if (st->controller->fd != NULL) {
+      fprintf(st->controller->fd, "%6.3f send  : %s\n", secondsOfMinute(), st->command);
+    }
+    if(st->controller != NULL){
+    	traceIO(st->controller->node->name, "transsend:%s", st->command);
+    } else {
+    	traceIO("sctunknown", "transsend:%s", st->command);
+    }
     return st->command;
   } else {
     st->sent = 2;
     if (st->controller->verbose) {
       SCPrintf(st->con, eLog, "%6.3f reply : %s", secondsOfMinute(), lastReply);
     }
+    if (st->controller->fd != NULL) {
+      fprintf(st->controller->fd,"%6.3f reply : %s\n", secondsOfMinute(), lastReply);
+    }
     /* printf("Transact: %s got %s\n", st->command, lastReply); */
+    if(st->controller != NULL){
+    	traceIO(st->controller->node->name, "transreply:%s", lastReply);
+    } else {
+    	traceIO("sctunknown", "transreply:%s", lastReply);
+    }
 
     st->reply = strdup(lastReply);
     return NULL;
@@ -1141,6 +1176,11 @@ static int SctTransactCmd(pSICSOBJ ccmd, SConnection * con,
 
   c = (SctController *) ccmd->pPrivate;
 
+  if(nPar < 1 || par[0] == NULL){
+	  SCWrite(con,"ERROR: no data to transact found", eError);
+	  return 0;
+  }
+
   st = calloc(sizeof(SctTransact), 1);
   if (st == NULL) {
     SCWrite(con, "ERROR: out of memory in SctTransactCommand", eError);
@@ -1239,14 +1279,14 @@ static int SctStatistics(pSICSOBJ ccmd, SConnection * con,
   char state[16];
 
   c = (SctController *) ccmd->pPrivate;
-  DevStatistics(c->devser,&avg, &max, &errCount, &errState);
+  DevStatistics(c->devser,&avg, &max, &maxCount, &errCount,  &errState);
   if(errState == 1){
 	  strcpy(state,"in error");
   } else {
 	  strcpy(state,"good");
   }
-  SCPrintf(con,eValue,"Average roundtrip time: %lf, maximum roundtrip time %lf, com error count: %ld, com state: %s",
+  SCPrintf(con,eValue,"Average roundtrip time: %lf, maximum roundtrip time %lf, count max roundtrip/2 %d, com error count: %ld, com state: %s",
-		  avg, max, errCount, state);
+		  avg, max, maxCount, errCount, state);
   DevAsconStatistics(c->devser,&avg, &max, &maxState, &maxCount);
   SCPrintf(con,eValue,"Average time in AsconTask: %lf, maximum time spent in AsconTask %lf, state of Ascon on max %d, count > max/2 %d",
 		  avg, max, maxState, maxCount);
@@ -1254,6 +1294,34 @@ static int SctStatistics(pSICSOBJ ccmd, SConnection * con,
   return 1;
 }
 
+static int SctLog(pSICSOBJ ccmd, SConnection * con,
+                         Hdb * cmdNode, Hdb * par[], int nPar)
+{
+  SctController *c;
+  char *filename = NULL;
+
+  c = (SctController *) ccmd->pPrivate;
+  filename = par[0]->value.v.text;
+  if(strcmp(filename,"close") == 0 ){
+	  if(c->fd != NULL){
+		  fclose(c->fd);
+		  c->fd = NULL;
+	  }
+  } else {
+	  if(c->fd != NULL){
+		  fclose(c->fd);
+	  }
+	  c->fd = fopen(filename,"w");
+	  if(c->fd == NULL){
+		  SCPrintf(con,eError,"ERROR: failed to open %s for logging", filename);
+		  return 0;
+	  } else {
+		  SCPrintf(con,eValue,"Logging to %s", filename);
+	  }
+  }
+  return 1;
+}
+
 static hdbCallbackReturn SctDebugCallback(Hdb * node, void *userData,
                                           hdbMessage * msg)
 {
@@ -1305,6 +1373,12 @@ static void SctKillController(void *c)
   }
   DevKill(controller->devser);
   controller->devser = NULL;
+
+  if(controller->fd != NULL){
+	  fclose(controller->fd);
+	  controller->fd = NULL;
+  }
+
   if (pServ->pTasker) {
     TaskRegister(pServ->pTasker, SctDeferredTask, NULL, SctDeferredFree,
                  controller, 0);
@@ -1395,6 +1469,11 @@ static int SctMakeController(SConnection * con, SicsInterp * sics,
   AddSICSHdbPar(cmd, "prio", usMugger, MakeHdbText("write"));
   AddSICSHdbPar(cmd, "action", usMugger, MakeHdbText("write"));
 
+
+  cmd = AddSICSHdbPar(controller->node,
+                      "log", usMugger, MakeSICSFunc(SctLog));
+  AddSICSHdbPar(cmd, "filename", usMugger, MakeHdbText(""));
+
   cmd = AddSICSHdbPar(controller->node,
                       "transact", usMugger, MakeSICSFunc(SctTransactCmd));
   AddSICSHdbPar(cmd, "data", usMugger, MakeHdbText(""));

sics.h

@@ -38,7 +38,7 @@ typedef enum {
 #include "nserver.h"
 #include "servlog.h"
 #include "sicsutil.h"
-
+#include "trace.h"
 
 extern pServer pServ;
 

sicshipadaba.c

@@ -2973,7 +2973,7 @@ static int HdbArrayNode(SConnection * pCon, SicsInterp * pSics, void *pData,
 	  }
 	  
 	  if(strcmp(argv[2], "init") == 0){
-		  v = makeHdbValue(node->value.dataType, length);
+		  v = makeHdbValue(node->value.dataType, node->value.arrayLength);
 		  switch(node->value.dataType){
 		  case HIPINTAR:
 		  case HIPINTVARAR:

sicsobj.c

@@ -543,7 +543,7 @@ pSICSOBJ SetupSICSOBJ(SConnection * pCon, SicsInterp * pSics, void *pData,
     priv = decodeSICSPriv(argv[3]);
     /* convert datatype */
     type = convertHdbType(argv[4]);
-    if (type > HIPFLOAT) {
+    if (type > HIPTEXT) {
       SCWrite(pCon,
               "ERROR: invalid type requested: none, int, float supported",
               eError);

sicsutil.c

@@ -11,6 +11,10 @@
 #include <sys/time.h>
 #include "fortify.h"
 #include "sics.h"
+#include "HistMem.h"
+#include "sicsdata.h"
+#include "SCinter.h"
+#include "sicshipadaba.h"
 
 static char *aCode[] = {
   "internal",
@@ -49,5 +53,87 @@ double DoubleTime(void)
   gettimeofday(&now, NULL);
   return now.tv_sec + now.tv_usec / 1e6;
 }
+/*--------------------------------------------------------------------------*/
+unsigned short fletcher16( char *data, size_t len)
+{
+        unsigned short sum1 = 0xff, sum2 = 0xff, result;
+        unsigned char checkA, checkB;
 
+        if(data == NULL){
+        	return 0;
+        }
+        while (len) {
+                size_t tlen = len > 21 ? 21 : len;
+                len -= tlen;
+                do {
+                        sum1 += *data++;
+                        sum2 += sum1;
+                } while (--tlen);
+                sum1 = (sum1 & 0xff) + (sum1 >> 8);
+                sum2 = (sum2 & 0xff) + (sum2 >> 8);
+        }
+        /* Second reduction step to reduce sums to 8 bits */
+        sum1 = (sum1 & 0xff) + (sum1 >> 8);
+        sum2 = (sum2 & 0xff) + (sum2 >> 8);
+        checkA = (unsigned char)sum1;
+        checkB = (unsigned char)sum2;
+        result = checkA;
+        result = result << 8 | checkB;
+        return result ;
+}
+/*--------------------------------------------------------------------------*/
+int CheckSum(SConnection * pCon, SicsInterp * pSics, void *pData,
+                     int argc, char *argv[])
+{
+	pHdb node = NULL;
+	unsigned short checksum;
+	pObjectDescriptor pDes = NULL;
+	pHistMem pHM;
+	int length;
+	char *data = NULL;
+	pSICSData sidata = NULL;
+
+	if(argc < 2){
+		SCWrite(pCon,"ERROR: need object to checksum", eError);
+		return 0;
+	}
+
+	node = FindHdbNode(NULL,argv[1],NULL);
+	if(node != NULL){
+		checksum = getHdbCheckSum(&node->value);
+		SCPrintf(pCon,eValue,"%d", checksum);
+		return 1;
+	}
+
+	pDes  = FindCommandDescriptor(pSics, argv[1]);
+	if(pDes == NULL){
+		SCPrintf(pCon,eError,"ERROR: object %s not found", argv[0]);
+		return 0;
+	}
+
+	if(strcmp(pDes->name, "HistMem") == 0){
+		pHM = (pHistMem)FindCommandData(pSics,argv[1],"HistMem");
+		if(argc < 3){
+			length = GetHistLength(pHM);
+			data = (char *)GetHistogramPointer(pHM,pCon);
+			checksum = fletcher16(data,length*sizeof(HistInt));
+			SCPrintf(pCon,eValue,"%d", checksum);
+			return 1;
+		} else {
+			data = (char *)GetHistTimeBin(pHM,&length);
+			checksum = fletcher16(data,length*sizeof(float));
+			SCPrintf(pCon,eValue,"%d", checksum);
+			return 1;
+		}
+	}
+
+	if(strcmp(pDes->name, "SICSData") == 0){
+		sidata = (pSICSData)FindCommandData(pSics,argv[1],"SICSData");
+		checksum = fletcher16((char *)sidata->data, sidata->dataUsed*sizeof(int));
+		SCPrintf(pCon,eValue,"%d", checksum);
+		return 1;
+	}
+	SCWrite(pCon,"ERROR: object type not recognized", eError);
+	return 0;
+}
 

sicsutil.h

@@ -14,4 +14,13 @@ double DoubleTime(void);
 /* returns time since epoch in seconds
    the resultion is machine dependent, but mostly better than msec */
 
+/**
+ * returns a checksum for data
+ *  /param data pointer to the data to checksum
+ *  /param len The length of data
+ *  /return a checksum
+ */
+unsigned short fletcher16( char *data, size_t len);
+
+
 

sicvar.c

@@ -55,7 +55,7 @@ static int VarSave(void *pData, char *name, FILE * fd)
   assert(pData);
   assert(fd);
   pVar = (pSicsVariable) pData;
-  if (pVar->iLock || pVar->iAccessCode == usInternal) {
+  if (pVar->iAccessCode == usInternal) {
     return 1;
   }
   snprintf(pBueffel,sizeof(pBueffel)-1, "# Variable %s\n", name);
@@ -243,6 +243,7 @@ int VarSetFloat(pSicsVariable self, float fNew, int iUserRights)
   } else {
     self->fVal = fNew;
     InvokeCallBack(self->pCall, VALUECHANGE, self);
+    tracePar(self->name,"%f",fNew);
   }
   return 1;
 }
@@ -258,6 +259,7 @@ int VarSetInt(pSicsVariable self, int iNew, int iUserRights)
   } else {
     self->iVal = iNew;
     InvokeCallBack(self->pCall, VALUECHANGE, self);
+    tracePar(self->name,"%d",iNew);
   }
   return 1;
 }
@@ -276,7 +278,8 @@ int VarSetText(pSicsVariable self, char *pNew, int iUserRights)
     }
     self->text = strdup(pNew);
     InvokeCallBack(self->pCall, VALUECHANGE, self);
-  }
+    tracePar(self->name,"%s",pNew);
+ }
   return 1;
 }
 
@@ -520,6 +523,11 @@ int VarWrapper(SConnection * pCon, SicsInterp * pInterp, void *pData,
     DeleteTokenList(pList);
     SCSendOK(pCon);
     return 1;
+  } else if (strcmp(pCurrent->text, "unlock") == 0) {
+    pVar->iLock = 0;
+    DeleteTokenList(pList);
+    SCSendOK(pCon);
+    return 1;
   } else if (strcmp(pCurrent->text, "force") == 0) {
     /*
        Undocumented feauture: force a set even while driving etc.

test/DataNumber

@@ -1,3 +1,3 @@
- 318 
+ 324 
 NEVER, EVER modify or delete this file
 You'll risk eternal damnation and a reincarnation as a cockroach!

test/sicsstat.tcl

@@ -44,6 +44,12 @@ lieselotte SetMode Timer
 # Counter multi
 multi SetPreset 0.000000
 multi SetMode Timer
+sicsdatapath ./
+sicsdatapath setAccess 1
+sicsdataprefix regression
+sicsdataprefix setAccess 1
+sicsdatapostfix .dat
+sicsdatapostfix setAccess 1
 # Motor a1
 a1 sign 1.000000
 a1 SoftZero 0.000000
@@ -251,7 +257,5 @@ cone qscale 1
 cone center unknown
 simidx sttlim 0.2
 simidx anglim 0.5
-apple preset 0
-apple mode monitor
 simi preset 0
 simi mode monitor

test/testini.tcl

@@ -215,6 +215,48 @@ hattach target a3 /target/ta3
 
 restore
 
+#==================================================
+# ScriptContext testing 
+#==================================================
+proc sendtest {} {
+    set test [catch {sct target} msg]
+    if {$test == 0} {
+	set data $msg
+    } else {
+	set data TestDuta
+    }
+    sct send $data
+    return testreply
+}
+#-------------------------------------------------
+proc readtest {} {
+    set t [doubletime]
+    sct send "Read:$t"
+    return testreply
+}
+#-------------------------------------------------
+proc testreply {} {
+    sct print [sct result]
+    sct update [sct result]
+    return idle
+}
+makesctcontroller testsct testprot
+MakeSICSObj testnode Test spy text
+hsetprop /sics/testnode read readtest
+hsetprop /sics/testnode write sendtest
+hsetprop /sics/testnode testreply testreply
+
+proc testprio {} {
+    testsct queue /sics/testnode read read
+    testsct queue /sics/testnode read read 
+    testsct queue /sics/testnode read read 
+    testsct queue /sics/testnode halt write
+    testsct queue /sics/testnode read read 
+    testsct queue /sics/testnode read read
+    return [testnode]
+}
+Publish testprio Spy
+
 #-------------------------------------------------
 proc farmFormat {par num} {
     hsetprop /sics/farm/$par lastError none
@@ -345,7 +387,7 @@ hsetprop /sics/farm/schneggecon readCommand   schget
 hsetprop /sics/farm/schneggecon replyCommand  schreply
 }
 
-set farm 0
+set farm 1
 
 if {$farm == 1} {
 #-------------- Test new async protocol controller
@@ -432,7 +474,7 @@ farmser poll /sics/farm/schneggerunning
 hfactory /sics/farm/stone plain spy int  
 hsetprop /sics/farm/stone read farmparcom stone
 hsetprop /sics/farm/stone parread farmparread
-#farmser poll /sics/farm/stone
+farmser poll /sics/farm/stone
 
 farmser debug -1
 

testprot.c

@@ -133,6 +133,8 @@ static void findResponse(Ascon *a)
 /*---------------------------------------------------------------------------*/
 static int TestProtHandler(Ascon * a)
 {
+  int i;
+
   switch (a->state) {
   case AsconConnectStart:
   case AsconConnecting:
@@ -146,6 +148,9 @@ static int TestProtHandler(Ascon * a)
 	  findResponse(a);
       break;
   case AsconReadStart:
+	  for(i = 0; i < 100; i++){
+		  TaskYield(pServ->pTasker);
+	  }
 	  a->state = AsconReading;
 	  break;
   case AsconReading:

trace.c

@@ -0,0 +1,482 @@
+/*
+ * This is the trace facility for SICS. En detail logging for debugging complex
+ * problems and more.
+ *
+ * This is ugly: I have to copy the code in the trace functions because I can only pass
+ * down the argptr to lower level functions. But if I need space I have to reinitialize
+ * that pointer....
+ *
+ * Another ugliness: this works fine as long as the messages are printed immediately.
+ * Due to the implementation in conman.c and rs232controller.c the id may change if
+ * there is a delay. If you need a queue, queue copies.
+ *
+ * There is another dependency here: the code in getTracePath relies on MakeSICSOBj
+ * setting the property sicsdev.
+ *
+ * trace.c
+ *
+ *  Created on: Apr 27, 2011
+ *      Author: koennecke
+ */
+
+#include <trace.h>
+#include <stdio.h>
+#include <sics.h>
+#include <sicshipadaba.h>
+#include <sicsobj.h>
+
+static FILE *log = NULL;
+static char *logfile = NULL;
+static int hdbInit = 0;
+static int filterProv = 0;
+static int debug = 0;
+/*----------------------------------------------------------------------------------------*/
+static char *GetTracePath(pHdb node)
+{
+	  pHdb nodeStack[64];
+	  int depth = 0, length = 0, i;
+	  pHdb current = NULL;
+	  char *pPtr = NULL;
+	  char sicsdev[80];
+
+	    /**
+	     * build a nodestack and find out required string length for path
+	     */
+	  current = node;
+	  while (current != NULL && GetHdbProperty(current,"sicsdev",sicsdev,sizeof(sicsdev)) == 0) {
+		  length += strlen(current->name) + 1;
+		  nodeStack[depth] = current;
+		  depth++;
+		  assert(depth < 64);
+		  current = current->mama;
+	  }
+	  if(current != NULL){
+		  length += strlen(current->name) + 2;
+		  nodeStack[depth] = current;
+		  depth++;
+	  }
+
+	  pPtr = malloc(length * sizeof(char));
+	  if (pPtr == NULL) {
+	    return NULL;
+	  }
+	  memset(pPtr, 0, length * sizeof(char));
+
+	  /*
+	   * we wish to decremement by one because above loop
+	   * increments one to many and we wish to ignore the
+	   * root node
+	   */
+	  for (i = depth - 1; i >= 0; i--) {
+	    strcat(pPtr, "/");
+	    strcat(pPtr, nodeStack[i]->name);
+	  }
+	  return pPtr;
+}
+/*----------------------------------------------------------------------------------------*/
+static hdbCallbackReturn TraceCallback(pHdb node, void *userData,
+                                            pHdbMessage message)
+{
+	pHdbDataMessage mm = NULL;
+	char *pPath = NULL;
+	pDynString result, printedData;
+
+	  if ((mm = GetHdbUpdateMessage(message)) == NULL) {
+	    return hdbContinue;
+	  }
+
+	  if(getHdbCheckSum(&node->value) == getHdbCheckSum(mm->v)){
+		  return hdbContinue;
+	  }
+
+	  pPath = GetTracePath(node);
+	  if(pPath == NULL){
+		  return hdbContinue;
+	  }
+
+	  if (mm->v->arrayLength < 20) {
+	    printedData = formatValue(*(mm->v), node);
+	    if (printedData == NULL ) {
+	    	return hdbContinue;
+	    }
+	    tracePar(pPath,"%s",GetCharArray(printedData));
+		DeleteDynString(printedData);
+	  } else {
+		  tracePar(pPath,"!!datachange!!");
+	  }
+	  free(pPath);
+
+	  return hdbContinue;
+}
+/*---------------------------------------------------------------------------*/
+int InstallTrace(pHdb node)
+{
+  pHdb currentChild = NULL;
+  pHdbCallback noty = NULL;
+
+  if(node->value.dataType == HIPOBJ || node->value.dataType == HIPFUNC){
+	  return 1;
+  }
+
+  noty = MakeHipadabaCallback(TraceCallback, NULL, NULL);
+  if (noty == NULL ) {
+     return 0;
+  }
+  AppendHipadabaCallback(node, noty);
+
+  currentChild = node->child;
+  while (currentChild != NULL) {
+	  InstallTrace(currentChild);
+      currentChild = currentChild->next;
+  }
+  return 1;
+}
+/*-----------------------------------------------------------------*/
+static void TraceObjects(void)
+{
+	CommandList *com = NULL;
+	pDummy dum = NULL;
+
+	com = pServ->pSics->pCList;
+	while(com != NULL){
+		dum = (pDummy)com->pData;
+		if(dum->pDescriptor->parNode != NULL){
+			InstallTrace(dum->pDescriptor->parNode);
+		}
+		com = com->pNext;
+	}
+}
+/*-----------------------------------------------------------------*/
+static int filterProvenance(char *sub, char *id)
+{
+	if(strstr(sub,"io") != NULL){
+		return 0;
+	}
+	if(strstr(sub,"sys") != NULL && strstr(id,"perfmon") != NULL){
+		return 0;
+	}
+	return 1;
+}
+/*-----------------------------------------------------------------*/
+static int filter(char *sub, char *id)
+{
+	if(filterProv != 0){
+		return filterProvenance(sub,id);
+	} else {
+		return 1;
+	}
+}
+/*-----------------------------------------------------------------*/
+static int strrepc(char *pszStr, char cFrom, char cTo)
+{
+      char  *ptr ;                              /* Pointer to string */
+      int   iReturn = 0 ;                       /* No of replacements */
+
+      /*----------------------------------------------------------------*/
+
+      while( 0 != ( ptr = strchr( pszStr, cFrom ) ) )
+
+      {     /* WHILE cFrom occurs in pszStr */
+
+            pszStr[ (int) ptr - (int) pszStr ] = cTo ;
+
+            /*- Replace next cFrom with cTo */
+
+            iReturn++ ;                                           /*- count */
+      }
+
+      return( iReturn ) ;
+}
+/*-----------------------------------------------------------------*/
+void traceprint(char *sub, char *id, char *data)
+{
+	if(log != NULL && filter(sub,id)){
+		strrepc(data,'\n',':');
+		fprintf(log,"%s:%s:%lf:%s\n", sub,id,DoubleTime(),data);
+	}
+}
+/*-----------------------------------------------------------------*/
+void traceIO(char *id, char *format, ...)
+{
+	va_list argptr;
+	char buffer[1024], *buf = NULL;
+	int len;
+
+	if(log != NULL && filter("io","id")){
+		va_start(argptr,format);
+		len = vsnprintf(buffer, sizeof(buffer),format,argptr);
+		va_end(argptr);
+		if(len >= sizeof(buffer)){
+			buf = malloc(len+1);
+			memset(buf,0,len+1);
+			if(buf != NULL){
+				va_start(argptr,format);
+				len = vsnprintf(buf, len+1,format,argptr);
+				va_end(argptr);
+				traceprint("io",id,buf);
+				free(buf);
+			}
+		} else {
+			traceprint("io",id,buffer);
+		}
+	}
+}
+/*-----------------------------------------------------------------*/
+void traceDevice(char *id, char *format, ...)
+{
+	va_list argptr;
+	char buffer[1024], *buf = NULL;
+	int len;
+
+	if(log != NULL && filter("dev","id")){
+		va_start(argptr,format);
+		len = vsnprintf(buffer, sizeof(buffer),format,argptr);
+		va_end(argptr);
+		if(len >= sizeof(buffer)){
+			buf = malloc(len+1);
+			memset(buf,0,len+1);
+			if(buf != NULL){
+				va_start(argptr,format);
+				len = vsnprintf(buf, len+1,format,argptr);
+				va_end(argptr);
+				traceprint("dev",id,buf);
+			}
+		} else {
+			traceprint("dev",id,buffer);
+		}
+	}
+}
+/*-----------------------------------------------------------------*/
+void traceCommand(char *id, char *format, ...)
+{
+	va_list argptr;
+	char buffer[1024], *buf = NULL;
+	int len;
+
+	if(log != NULL && filter("com","id")){
+		va_start(argptr,format);
+		len = vsnprintf(buffer, sizeof(buffer),format,argptr);
+		va_end(argptr);
+		if(len >= sizeof(buffer)){
+			buf = malloc(len+1);
+			memset(buf,0,len+1);
+			if(buf != NULL){
+				va_start(argptr,format);
+				len = vsnprintf(buf, len+1,format,argptr);
+				va_end(argptr);
+				traceprint("com",id,buf);
+			}
+		} else {
+			traceprint("com",id,buffer);
+		}
+	}
+}
+/*-----------------------------------------------------------------*/
+void tracePar(char *id, char *format, ...)
+{
+	va_list argptr;
+	char buffer[1024], *buf = NULL;
+	int len;
+
+	if(log != NULL && filter("par","id")){
+		va_start(argptr,format);
+		len = vsnprintf(buffer, sizeof(buffer),format,argptr);
+		va_end(argptr);
+		if(len >= sizeof(buffer)){
+			buf = malloc(len+1);
+			memset(buf,0,len+1);
+			if(buf != NULL){
+				va_start(argptr,format);
+				len = vsnprintf(buf, len+1,format,argptr);
+				va_end(argptr);
+				traceprint("par",id,buf);
+			}
+		} else {
+			traceprint("par",id,buffer);
+		}
+	}
+}
+/*-----------------------------------------------------------------*/
+void traceSys(char *id, char *format, ...)
+{
+	va_list argptr;
+	char buffer[1024], *buf = NULL;
+	int len;
+
+	if(log != NULL && filter("sys","id")){
+		va_start(argptr,format);
+		len = vsnprintf(buffer, sizeof(buffer),format,argptr);
+		va_end(argptr);
+		if(len >= sizeof(buffer)){
+			buf = malloc(len+1);
+			memset(buf,0,len+1);
+			if(buf != NULL){
+				va_start(argptr,format);
+				len = vsnprintf(buf, len+1,format,argptr);
+				va_end(argptr);
+				traceprint("sys",id,buf);
+			}
+		} else {
+			traceprint("sys",id,buffer);
+		}
+	}
+}
+/*-----------------------------------------------------------------*/
+void traceDebug(char *id, char *format, ...)
+{
+	va_list argptr;
+	char buffer[1024], *buf = NULL;
+	int len;
+
+	if(log != NULL && debug == 1){
+		va_start(argptr,format);
+		len = vsnprintf(buffer, sizeof(buffer),format,argptr);
+		va_end(argptr);
+		if(len >= sizeof(buffer)){
+			buf = malloc(len+1);
+			memset(buf,0,len+1);
+			if(buf != NULL){
+				va_start(argptr,format);
+				len = vsnprintf(buf, len+1,format,argptr);
+				va_end(argptr);
+				traceprint("debug",id,buf);
+			}
+		} else {
+			traceprint("debug",id,buffer);
+		}
+	}
+}
+/*----------------------------------------------------------------*/
+static void saveInitialParameters()
+{
+	CommandList *pCom = NULL;
+	char prefix[512];
+	pIDrivable pDriv = NULL;
+	float value;
+	pDummy pDum = NULL;
+
+	if(log == NULL){
+		return;
+	}
+
+	pCom = pServ->pSics->pCList;
+	while(pCom != NULL){
+		if(strcmp(pCom->pName,"restore") == 0){
+			pCom = pCom->pNext;
+			continue;
+		}
+		snprintf(prefix,sizeof(prefix),"par:start:%s", pCom->pName);
+		pDum = (pDummy)pCom->pData;
+		if(pDum != NULL){
+			pDum->pDescriptor->SaveStatus(pCom->pData,prefix, log);
+			pDriv = pDum->pDescriptor->GetInterface(pCom->pData, DRIVEID);
+			if(pDriv != NULL){
+				value = pDriv->GetValue(pCom->pData,pServ->dummyCon);
+				fprintf(log,"%s:%f\n", prefix,value);
+			}
+		}
+		pCom = pCom->pNext;
+	}
+	fprintf(log,"par:start:EOF\n");
+}
+/*----------------------------------------------------------------*/
+static int TraceLog(pSICSOBJ ccmd, SConnection * con,
+                         Hdb * cmdNode, Hdb * par[], int nPar)
+{
+  char *filename = NULL;
+
+  if(nPar < 1) {
+	  if(log != NULL){
+		  SCPrintf(con,eValue,"Tracing to %s", logfile);
+	  } else {
+		  SCWrite(con,"Tracing is off", eValue);
+	  }
+	  return 1;
+  }
+
+  filename = par[0]->value.v.text;
+  if(strcmp(filename,"close") == 0 ){
+	  if(log != NULL){
+		  fclose(log);
+		  log = NULL;
+		  SCPrintf(con,eValue,"Tracing to %s closed", logfile);
+		  free(logfile);
+	  }
+  } else {
+	  if(log != NULL){
+		  fclose(log);
+		  free(logfile);
+	  }
+	  log = fopen(filename,"w");
+	  if(log == NULL){
+		  SCPrintf(con,eError,"ERROR: failed to open %s for logging", filename);
+		  return 0;
+	  } else {
+		  logfile = strdup(filename);
+		  saveInitialParameters();
+		  SCPrintf(con,eValue,"Logging to %s", filename);
+		  if(hdbInit == 0){
+			  TraceObjects();
+			  hdbInit = 1;
+		  }
+	  }
+  }
+  return 1;
+}
+/*-----------------------------------------------------------------------------*/
+static int TraceDebug(pSICSOBJ ccmd, SConnection * con,
+                         Hdb * cmdNode, Hdb * par[], int nPar)
+{
+	if(nPar >= 1){
+		debug = par[0]->value.v.intValue;
+	}
+	SCPrintf(con,eValue, "trace.debug = %d", debug);
+	return 1;
+}
+/*-----------------------------------------------------------------------------*/
+static int TraceFilter(pSICSOBJ ccmd, SConnection * con,
+                         Hdb * cmdNode, Hdb * par[], int nPar)
+{
+	if(nPar >= 1){
+		filterProv = par[0]->value.v.intValue;
+	}
+	SCPrintf(con,eValue, "trace.filter = %d", filterProv);
+	return 1;
+}
+/*-----------------------------------------------------------------------------*/
+static void KillTrace(void *data)
+{
+	if(log != NULL){
+		fclose(log);
+		free(logfile);
+		log = NULL;
+		logfile = NULL;
+	}
+}
+/*-----------------------------------------------------------------------------------------*/
+void MakeTrace(void)
+{
+  SICSOBJ *ccmd;
+  pHdb cmd;
+
+  ccmd = MakeSICSOBJv("trace", "SicsTrace", HIPNONE, usSpy);
+  if(ccmd == NULL){
+	  SCWrite(pServ->dummyCon,"ERROR: out of memory creating trace", eError);
+	  return;
+  }
+
+  cmd = AddSICSHdbPar(ccmd->objectNode,
+                      "log", usMugger, MakeSICSFunc(TraceLog));
+  AddSICSHdbPar(cmd, "filename", usMugger, MakeHdbText(""));
+
+  cmd = AddSICSHdbPar(ccmd->objectNode,
+                      "filter", usMugger, MakeSICSFunc(TraceFilter));
+  AddSICSHdbPar(cmd, "selection", usMugger, MakeHdbInt(0));
+
+  cmd = AddSICSHdbPar(ccmd->objectNode,
+                      "debug", usMugger, MakeSICSFunc(TraceDebug));
+  AddSICSHdbPar(cmd, "switch", usMugger, MakeHdbInt(0));
+
+  AddCommand(pServ->pSics, "trace", InterInvokeSICSOBJ, KillTrace, ccmd);
+
+}

trace.h

@@ -0,0 +1,32 @@
+/*
+ * This is the trace facility for SICS. En detail logging for debugging complex
+ * problems and more.
+ *
+ * trace.h
+ *
+ *  Created on: Apr 27, 2011
+ *      Author: koennecke
+ */
+
+#ifndef TRACE_H_
+#define TRACE_H_
+#include <stdarg.h>
+
+/**
+ * printf style functions for printing trace information
+ * from various sub systems. The id field is something like
+ * the socket number, a host:port or something appropriate
+ * which tells us where the stuff is going to or coming from.
+ */
+void traceIO(char *id, char *format, ...);
+void traceDevice(char *id, char *format, ...);
+void traceCommand(char *id, char *format, ...);
+void tracePar(char *id, char *format, ...);
+void traceSys(char *id, char *format, ...);
+void traceprint(char *sub, char *id,char *data);
+
+/**
+ * A debugging trace. This has to be switched on separately
+ */
+void traceDebug(char *id, char *format, ...);
+#endif /* TRACE_H_ */