lowcal: improved debugging and error reporting for PROT_UMSG/PROT_2LATE

MultiCAN/src/protocol/LowCAL/lowcal.c

@@ -304,6 +304,27 @@ void ext_prot_err(int status, const char* msg,
    );
 }
 
+#ifdef LCAL_STAT
+/*
+ * Further extended version of prot_err, prints information about stats, too.
+ */
+void ext_stat_prot_err(int status, const char* msg,
+   unsigned port, unsigned id, unsigned mux, byte* data,
+   Buf_Stat *pstat)
+{
+   prot_err(status,
+      "%s: port=%u id=%u mux=%u data=%02x %02x %02x %02x %02x %02x %02x %02x\n"
+      "  enq=%lu req=%lu resp=%lu:\n",
+      msg, port, id, mux,
+      data[0], data[1], data[2], data[3],
+      data[4], data[5], data[6], data[7],
+      (unsigned long)pstat->enqueue_time,
+      (unsigned long)pstat->request_time,
+      (unsigned long)pstat->response_time
+   );
+}
+#endif
+
 /*+**************************************************************************
  *
  * Function:	var2buf
@@ -1908,8 +1929,15 @@ prot_Return lowcal_put (
    }
 				/* Discard if msg is too late */
    if (slot_p->flags.timeout) {
+#ifdef LCAL_STAT
+      alm_stamp_t now = alm_get_stamp();
+      slot_p->stat.response_time = now;
+      ext_stat_prot_err(PROT_2LATE, myname, slot_p->varset_p->addr.port,
+         slot_p->varset_p->addr.in_id, mux, data_p, &slot_p->stat);
+#else
       ext_prot_err(PROT_2LATE, myname, slot_p->varset_p->addr.port,
          slot_p->varset_p->addr.in_id, mux, data_p);
+#endif
       epicsMutexUnlock(mutex);
       return(PROT_OK);
    }
@@ -1918,8 +1946,15 @@ prot_Return lowcal_put (
         slot_p->flags.state != LCAL_PENDING) ||
        (attrib.user == LCAL_SERVER &&
         slot_p->flags.state == LCAL_ENQUEUED)) {
+#ifdef LCAL_STAT
+      alm_stamp_t now = alm_get_stamp();
+      slot_p->stat.response_time = now;
+      ext_stat_prot_err(PROT_UMSG, myname, slot_p->varset_p->addr.port,
+         slot_p->varset_p->addr.in_id, mux, data_p, &slot_p->stat);
+#else
       ext_prot_err(PROT_UMSG, myname, slot_p->varset_p->addr.port,
          slot_p->varset_p->addr.in_id, mux, data_p);
+#endif
       epicsMutexUnlock(mutex);
       return(PROT_OK);
    }
@@ -2246,12 +2281,14 @@ prot_Return lowcal_time (mcan_Obj_Handle* obj_handle_p,
 #endif
 
 #if 0
-         errlogPrintf("lowcal_time: timeout for p=%d,o=%x,i=%x,m=%d,w=%lld\n",
-            slot_p->varset_p->addr.port,
-            slot_p->varset_p->addr.out_id,
-            slot_p->varset_p->addr.in_id,
-            slot_p->var_attrib.multiplexor,
-            now - slot_p->stat.request_time);
+         {
+            errlogPrintf("lowcal_time: timeout for p=%d,o=%x,i=%x,m=%d,w=%ld\n",
+               slot_p->varset_p->addr.port,
+               slot_p->varset_p->addr.out_id,
+               slot_p->varset_p->addr.in_id,
+               slot_p->var_attrib.multiplexor,
+               (long)(now - slot_p->stat.request_time));
+         }
 #endif
 
 	 slot_p->flags.timeout = TRUE;