From fd064f3df9b597092d33914e641eb835f2008adb Mon Sep 17 00:00:00 2001 From: Douglas Clowes Date: Tue, 13 Nov 2012 13:38:25 +1100 Subject: [PATCH] revise logging and state trace r3790 | dcl | 2012-11-13 13:38:25 +1100 (Tue, 13 Nov 2012) | 1 line --- site_ansto/motor_dmc2280.c | 243 ++++++++++++++++++++++--------------- 1 file changed, 147 insertions(+), 96 deletions(-) diff --git a/site_ansto/motor_dmc2280.c b/site_ansto/motor_dmc2280.c index 96303a0b..702a0efc 100644 --- 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: