revise logging and state trace

r3790 | dcl | 2012-11-13 13:38:25 +1100 (Tue, 13 Nov 2012) | 1 line
2012-11-13 13:38:25 +11:00
parent fa18677fca
commit fd064f3df9
1 changed files with 147 additions and 96 deletions
--- a/site_ansto/motor_dmc2280.c
+++ b/site_ansto/motor_dmc2280.c
@ -62,7 +62,10 @@ typedef struct EvtEvent_s EvtEvent, *pEvtEvent;

 typedef void (*StateFunc)(pDMC2280Driv self, pEvtEvent event);

-typedef struct EvtState_s { } EvtState;
+typedef struct EvtState_s {
+  StateFunc oldState;
+  StateFunc newState;
+} EvtState;

 typedef struct EvtTimer_s {
  int timerValue;
@ -223,6 +226,8 @@ struct __MoDriv {
  int variables;
 #if defined(STATE_TRACE) && (STATE_TRACE > 0)
  int state_trace_idx;
+  int state_trace_old;
+  char state_trace_done[STATE_TRACE];
  char state_trace_text[STATE_TRACE][CMDLEN];
  struct timeval state_trace_time[STATE_TRACE];
 #endif
@ -772,11 +777,21 @@ static int SendCallback(pAsyncTxn pCmd) {
      case '?':
        strncpy(self->lastCmd, pCmd->out_buf, CMDLEN);
        strncpy(self->dmc2280Error, &resp[1], CMDLEN);
+        SICSLogWrite("SendCallback: BADCMD", eError);
        SICSLogWrite(cmnd, eError);
        SICSLogWrite(resp, eError);
        self->errorCode = BADCMD;
        break;
      default:
+        if ((cmnd[0] == 'M' && cmnd[1] == 'G') || (cmnd[0] == 'L' && cmnd[1] == 'V')) {
+          /* MG and LV commands can produce this result */
+          if (self->debug) {
+            SICSLogWrite(cmnd, eStatus);
+            SICSLogWrite(resp, eStatus);
+          }
+          break;
+        }
+        SICSLogWrite("SendCallback: BADUNKNOWN", eError);
        SICSLogWrite(cmnd, eError);
        SICSLogWrite(resp, eError);
        self->errorCode = BADUNKNOWN;
@ -837,13 +852,14 @@ static int DMC_SendReceive(pDMC2280Driv self, char *cmd, char* reply) {
  }

  switch (reply[0]) {
-    case ':':
+    case ':': /* prompt */
      if (self->debug) {
        SICSLogWrite(cmd, eStatus);
        SICSLogWrite(reply, eStatus);
      }
      return SUCCESS;
-    case ' ':
+    case ' ': /* leading blank */
+    case '-': /* leading minus sign */
      if (self->debug) {
        SICSLogWrite(cmd, eStatus);
        SICSLogWrite(reply, eStatus);
@ -852,13 +868,23 @@ static int DMC_SendReceive(pDMC2280Driv self, char *cmd, char* reply) {
    case '?':
      strncpy(self->lastCmd, cmd, CMDLEN);
      strncpy(self->dmc2280Error, &reply[1], CMDLEN);
+      SICSLogWrite("DMC_SendReceive: BADCMD", eError);
      SICSLogWrite(cmd, eError);
      SICSLogWrite(reply, eError);
      self->errorCode = BADCMD;
      return FAILURE;
    default:
+      if ((cmd[0] == 'M' && cmd[1] == 'G') || (cmd[0] == 'L' && cmd[1] == 'V')) {
+        /* MG and LV commands can produce this result */
+        if (self->debug) {
+          SICSLogWrite(cmd, eStatus);
+          SICSLogWrite(reply, eStatus);
+        }
+        return SUCCESS;
+      }
      strncpy(self->lastCmd, cmd, CMDLEN);
      strncpy(self->dmc2280Error, &reply[0], CMDLEN);
+      SICSLogWrite("DMC_SendReceive: BADUNKNOWN", eError);
      SICSLogWrite(cmd, eError);
      SICSLogWrite(reply, eError);
      self->errorCode = BADUNKNOWN;
@ -1503,20 +1529,32 @@ static int rspPoll(pDMC2280Driv self, const char* text) {
 static void state_trace_prn(pDMC2280Driv self) {
 #if defined(STATE_TRACE) && (STATE_TRACE > 0)
  int idx = self->state_trace_idx;
-  SICSLogWrite("state_trace_prn trace listing start", eStatus);
+  int lines_printed = 0;
+  struct timeval tv;
+  gettimeofday(&tv, NULL);
  do {
    char* line;
    struct timeval *tp;
-    tp = &self->state_trace_time[self->state_trace_idx];
-    line = &self->state_trace_text[self->state_trace_idx++][0];
-    if (self->state_trace_idx >= STATE_TRACE)
-      self->state_trace_idx = 0;
-    if (*line)
+    tp = &self->state_trace_time[idx];
+    if (self->state_trace_done[idx])
+      line = NULL;
+    else
+      line = &self->state_trace_text[idx][0];
+    if (line && *line) {
+      if (lines_printed == 0)
+        /* print the opening message only if there are lines to print */
+        SICSLogTimePrintf(eStatus, &tv, "Motor: %s, state_trace_prn trace history listing start", self->name);
      SICSLogWriteTime(line, eStatus, tp);
+      lines_printed++;
+    }
+    self->state_trace_done[idx] = 1;
+    if (++idx >= STATE_TRACE)
+      idx = 0;
  } while (idx != self->state_trace_idx);
-  SICSLogWrite("state_trace_prn trace listing end", eStatus);
+  /* print a close message, even if there are zero lines */
+  SICSLogTimePrintf(eStatus, &tv, "Motor: %s, state_trace_prn trace history listing end (%d entries)", self->name, lines_printed);
 #else
-      SICSLogWrite("state_trace_prn not implemented", eStatus);
+  SICSLogPrintf(eStatus, "Motor: %s, state_trace_prn not implemented", self->name);
 #endif
 }

@ -1548,17 +1586,38 @@ static char* state_name(StateFunc func) {
 static void str_n_cat(char* s1, int len, const char* s2) {
  int i = strlen(s1);
  const char* p = s2;
-  while (i < len - 3 && *p) {
+  while (i < len - 1 && *p) {
    if (*p == '\r') {
+      if (i >= len -3)
+        break;
      s1[i++] = '\\';
      s1[i++] = 'r';
      ++p;
    }
    else if (*p == '\n') {
+      if (i >= len -3)
+        break;
      s1[i++] = '\\';
      s1[i++] = 'n';
      ++p;
    }
+    else if (*p == '\t') {
+      if (i >= len -3)
+        break;
+      s1[i++] = '\\';
+      s1[i++] = 't';
+      ++p;
+    }
+    else if (*p < ' ' || *p > '~') {
+      const char hex[] = "0123456789ABCDEF";
+      if (i >= len -5)
+        break;
+      s1[i++] = '<';
+      s1[i++] = hex[(*p >> 4) & 0xF];
+      s1[i++] = hex[(*p) & 0xF];
+      s1[i++] = '>';
+      ++p;
+    }
    else
      s1[i++] = *p++;
  }
@ -1568,7 +1627,9 @@ static void str_n_cat(char* s1, int len, const char* s2) {
 static char* event_name(pEvtEvent event, char* text, int length) {
  switch (event->event_type) {
    case eStateEvent:
-      snprintf(text, length, "eStateEvent");
+      snprintf(text, length, "eStateEvent (%s => %s)",
+          state_name(event->event.sta.oldState),
+          state_name(event->event.sta.newState));
      return text;
    case eTimerEvent:
      snprintf(text, length, "eTimerEvent (%d mSec)", event->event.tmr.timerValue);
@ -1605,119 +1666,108 @@ static char* event_name(pEvtEvent event, char* text, int length) {
  }
 }

-static void report_event(pDMC2280Driv self, pEvtEvent event) {
+static void state_trace_ins(pDMC2280Driv self, const char *fmt, ...) {
+  va_list ap;
+  char line[CMDLEN];
+  char *lp = line;
 #if defined(STATE_TRACE) && (STATE_TRACE > 0)
-  if (true) {
-    char* line;
-    gettimeofday(&self->state_trace_time[self->state_trace_idx], NULL);
-    line = &self->state_trace_text[self->state_trace_idx++][0];
-    if (self->state_trace_idx >= STATE_TRACE)
-      self->state_trace_idx = 0;
+  gettimeofday(&self->state_trace_time[self->state_trace_idx], NULL);
+  lp = &self->state_trace_text[self->state_trace_idx][0];
+  self->state_trace_done[self->state_trace_idx] = 0;
+  if (true)
 #else
-  if (self->debug || self->trace) {
-    char line[CMDLEN];
+  if (self->debug || self->trace)
 #endif
-    char text[CMDLEN];
-    snprintf(line, CMDLEN, "Motor=%s, State=%s(%d), event=%s",
+  {
+    char format[CMDLEN];
+    snprintf(format, CMDLEN, "Motor=%s, State=%s(%d), %s",
        self->name,
        state_name(self->myState),
        self->subState,
-        event_name(event, text, CMDLEN));
+        fmt);
+    va_start(ap, fmt);
+    vsnprintf(lp, CMDLEN, format, ap);
+    va_end(ap);
    if (self->debug)
-      SICSLogWrite(line, eStatus);
+      SICSLogWrite(lp, eStatus);
    if (self->trace)
-      SCWrite(self->trace, line, eStatus);
+      SCWrite(self->trace, lp, eStatus);
  }
+#if defined(STATE_TRACE) && (STATE_TRACE > 0)
+  if (++self->state_trace_idx >= STATE_TRACE)
+    self->state_trace_idx = 0;
+#endif
+}
+
+static void report_event(pDMC2280Driv self, pEvtEvent event) {
+#if defined(STATE_TRACE) && (STATE_TRACE > 0)
+  if (true)
+#else
+  if (self->debug || self->trace)
+#endif
+  {
+    char text[CMDLEN];
+    state_trace_ins(self, "Event=%s",
+        event_name(event, text, CMDLEN));
+  }
+}
+
+static void unhandled_event(pDMC2280Driv self, pEvtEvent event) {
+  char text[CMDLEN];
+  state_trace_ins(self, "Unhandled Event=%s",
+      event_name(event, text, CMDLEN));
+}
+
+static void handle_event(pDMC2280Driv self, pEvtEvent event) {
+#if defined(STATE_TRACE) && (STATE_TRACE > 0)
+  if (true)
+#else
+  if (self->debug || self->trace)
+#endif
+  {
+    report_event(self, event);
+  }
+  self->myState(self, event);
 }

 static void change_state(pDMC2280Driv self, StateFunc func) {
 #if defined(STATE_TRACE) && (STATE_TRACE > 0)
-  if (true) {
-    char* line;
-    gettimeofday(&self->state_trace_time[self->state_trace_idx], NULL);
-    line = &self->state_trace_text[self->state_trace_idx++][0];
-    if (self->state_trace_idx >= STATE_TRACE)
-      self->state_trace_idx = 0;
+  if (true)
 #else
-  if (self->debug || self->trace) {
-    char line[CMDLEN];
+  if (self->debug || self->trace)
 #endif
-    snprintf(line, CMDLEN, "Motor=%s, OldState=%s(%d), NewState=%s",
-        self->name,
-        state_name(self->myState),
-        self->subState,
+  {
+    state_trace_ins(self, "NewState=%s",
        state_name(func));
-    if (self->debug)
-      SICSLogWrite(line, eStatus);
-    if (self->trace)
-      SCWrite(self->trace, line, eStatus);
  }
  self->myPrevState = self->myState;
  self->myState = func;
  self->subState = 0;
  EvtEvent evt;
  evt.event_type = eStateEvent;
+  evt.event.sta.oldState = self->myPrevState;
+  evt.event.sta.newState = self->myState;
  self->myState(self, &evt);
 }

-static void unhandled_event(pDMC2280Driv self, pEvtEvent event) {
-#if defined(STATE_TRACE) && (STATE_TRACE > 0)
-    char* line;
-    gettimeofday(&self->state_trace_time[self->state_trace_idx], NULL);
-    line = &self->state_trace_text[self->state_trace_idx++][0];
-    if (self->state_trace_idx >= STATE_TRACE)
-      self->state_trace_idx = 0;
-#else
-    char line[CMDLEN];
-#endif
-    char text[CMDLEN];
-    snprintf(line, CMDLEN, "Motor=%s, State=%s(%d), unhandled event=%s",
-        self->name,
-        state_name(self->myState),
-        self->subState,
-        event_name(event, text, CMDLEN));
-    SICSLogWrite(line, eError);
-}
-
-static void handle_event(pDMC2280Driv self, pEvtEvent event) {
-  StateFunc oldState;
-#if defined(STATE_TRACE) && (STATE_TRACE > 0)
-#else
-  if (self->debug || self->trace)
-#endif
-    report_event(self, event);
-  oldState = self->myState;
-  self->myState(self, event);
-}
-
 static int state_snd_callback(pAsyncTxn pCmd) {
  pDMC2280Driv self = (pDMC2280Driv) pCmd->cntx;
  SendCallback(pCmd);
 #if defined(STATE_TRACE) && (STATE_TRACE > 0)
-  char* line;
-  char text[CMDLEN];
-  gettimeofday(&self->state_trace_time[self->state_trace_idx], NULL);
-  line = &self->state_trace_text[self->state_trace_idx++][0];
-  if (self->state_trace_idx >= STATE_TRACE)
-    self->state_trace_idx = 0;
+  if (true)
 #else
-  char line[CMDLEN];
-  char text[CMDLEN];
+  if (self->debug || self->trace)
 #endif
-  text[0] = '\0';
-  str_n_cat(text, CMDLEN, pCmd->out_buf);
-  str_n_cat(text, CMDLEN, "|");
-  str_n_cat(text, CMDLEN, pCmd->inp_buf);
-  snprintf(line, CMDLEN, "Motor=%s, State=%s(%d), send complete=%s",
-      self->name,
-      state_name(self->myState),
-      self->subState,
-      text);
-  if (self->debug)
-    SICSLogWrite(line, eStatus);
-  if (self->trace)
-    SCWrite(self->trace, line, eStatus);
-  return 0;
+  {
+    char text[CMDLEN];
+    text[0] = '\0';
+    str_n_cat(text, CMDLEN, pCmd->out_buf);
+    str_n_cat(text, CMDLEN, "|");
+    str_n_cat(text, CMDLEN, pCmd->inp_buf);
+    state_trace_ins(self, "Send Complete=%s",
+        text);
+    return 0;
+  }
 }

 static int state_msg_callback(pAsyncTxn pCmd) {
@ -2760,7 +2810,8 @@ static void DMCState_MotorStop(pDMC2280Driv self, pEvtEvent event) {
 static void DMCState_Error(pDMC2280Driv self, pEvtEvent event) {
  switch (event->event_type) {
    case eStateEvent:
-      state_trace_prn(self);
+      if (self->myPrevState != self->myState)
+        state_trace_prn(self);
      return;
    case eTimerEvent:
    case eMessageEvent: